Why does the second `untilNow` take 5us extra?

Help
1

This Zig 0.16 example:

const std = @import("std");

pub fn main(init: std.process.Init) !void {
    const io = init.io;

    const clk: std.Io.Clock = .awake;

    const start_time = clk.now(io);
    const t1 = start_time.untilNow(io, clk);
    const t2 = start_time.untilNow(io, clk);
    const t3 = start_time.untilNow(io, clk);
    const t4 = start_time.untilNow(io, clk);
    std.debug.print("{:>5}\n", .{@abs(t1.nanoseconds)});
    std.debug.print("{:>5}\n", .{@abs(t2.nanoseconds)});
    std.debug.print("{:>5}\n", .{@abs(t3.nanoseconds)});
    std.debug.print("{:>5}\n", .{@abs(t4.nanoseconds)});
}

prints (on Android Termux Linux):

  573
 5781
 6146
 6459

Why does the second call add an extra delay? (I’ve seen up to 8us.)

1 Like
2

I’m not an expert, but I would guess that, since accessing the timer requires IO, such tiny delays are just to be expected.

3

What I don’t get is why it’s consistently the second invocation that has the delay.

4

I was curious so I also ran your program on my machine. I observe the behavior you describe in Debug mode, but not in ReleaseFast or even ReleaseSafe. I imagine there’s something special happening with the Io interface in debug mode.

5

Try a warmup loop before you measure. Your first call is likely sneaking in before the OS triggers an unrelated set of operations on startup. cpu frequency change for example.

1 Like
6

Ok, so I’m home, and on my desktop Linux (x86-64 - Android is aarch64) - also in Debug mode - I get less consistent results, which is actually less surprising to me than having the weird delay on the second call every time: (changed clk to .real which makes no difference)

  346
  663
  853
 1059

 1642
 3763
 4493
 5223

(examples of two kinds of results I get)

7

I suspect you’re on to something. Inserting (before clk.now):

    for (0..500_000) |_| {
        std.atomic.spinLoopHint();
    }

makes the subsequent untilNow calls more consistent (around 300ns) on desktop Linux, but now on Android the delay of the second untilNow call is consistently at around 13us.

8

Note that just because it appears after the second call, does not mean it originated from the second call.
Internally untilNow does some stuff, then it gets the real time stamp, then it does some more stuff. That second part is not included in the first measurement.
As far as I can see untilNow (in debug mode) calls into multiple functions (→most likely icache misses) after it measured the time to compute the time difference. So this is a possibly explanation.

9

Oh, that is interesting. First time I ran it was smaller than the rest:

  470
 1959
 2084
 2194

  608
 4140
 4312
 4569

  596
 4509
 4645
 4762

zig-0.16.0, debug mode, .triple = “x86_64-linux.6.12.101…6.12.101-gnu.2.41”

EDIT: never mind, it’s probably because my computer has heterogenous CPU cores. It happens every I delete the zig-out directory - I think the compilation process makes the scheduler think it’s CPU-bound and put it onto a performance core.

1 Like
10

On modern operating systems (e.g. not 1980s 8- and 16-bit home computers) I would fully expect such random noise up to even milliseconds (assuming this is ‘wall clock time’).

Your program can be randomly interrupted at any time by the operating system’s scheduler and you have absolutely no control over when and for how long such scheduling gaps might occur. On top of that there may be random caching/warmup effects, or variable CPU clocks or performance-vs-efficiency cores on laptops.

Modern operating systems (and the hardware they run on) are simply the complete opposite of ‘realtime’, and they may suffer a lot from ‘noisy neighbours’.

For instance when running a game loop it’s not unusual that the per-frame code has a ‘scheduling jitter’ of one or two milli(!)seconds when the code is vsync-throttled, e.g. even though the presentation itself is absolutely on time, that doesn’t mean that your render thread wakes up in a predictable time window after vsync occured, it can be anywhere between 0.5 and 2 milliseconds late.

TL;DR: any sort of accurate time measurement on modern operating systems is a complete mess and shouldn’t be trusted :wink:

6 Likes
11

Preaching to the choir. I much prefer microcontrollers in that respect, much less stuff in between your code and the cpu. Just the other day I needed to make an ESP32-S3 output a PPS signal, and even with the most trivial code it was < 10us of jitter.

Holy shit, it’s that bad? That explains a lot.

12

Thanks for the responses. I’m beginning some debugging of hairy multithreaded code and I did this small experiment to figure out roughly what to expect from time measurements in terms of reliability / consistency. Now I won’t be too surprised to see random delays on the order of 10us.