Clock costs and a worked hop

What it costs

Read against the budget, the cheapest trustworthy timestamp, a fenced read, is 2–3% of a microsecond, and an interval needs two. A measurement that brackets every stage with a pair of reads spends 4–6% of the budget per stage on the clock alone, which is where the ladder of what measuring costs begins.

Worked example: one hop, 460 ticks

A run on a machine whose TSC ticks at 3.4 GHz stamps the update with sequence number 1,873,465,902 twice. On core 2, now() just before the decode reads t0 = 881,276,034,551,240. On core 3, inside the closure drain calls for it, now() reads t2 = 881,276,034,551,700. The difference is 460 ticks, and divided by 3.4 ticks per nanosecond it is 135 ns. The p50 of back-to-back now() pairs on the same machine is 82 ticks, 24 ns, which is the clock’s own share of any interval, since the closing read’s cost lands inside it. So about 111 ns belong to the path: the decode, the stamp at t1, the push into the ring, the trip of the slot’s line and the head line to core 3, and the poll that found them. That is inside the 90–230 ns the capstone’s prediction gives decode and hop together.

The figure means that only because three things hold. Both readings came from one synchronised counter: cores 2 and 3 are on one socket, sharing an L3, and the boot log shows no warp. Each reading was taken where it says: both threads are pinned, and now_cpu() at the start and end of the run returned 2 and 3. And the divisor is the TSC frequency, 3.4 GHz from the boot log and from calibrate(), not the 4.0 GHz the cores were running at, which would have given 115 ns.

Break any of the three and the number stays plausible. If core 3’s counter ran 300 ticks ahead of core 2’s, the same hop would read 760 ticks, 224 ns, and look like a transfer across sockets. If it ran 500 behind, the difference would be −40 ticks, which as a u64 is 170 years, clamped to 1 s by the histogram. If the feed thread were unpinned and had moved to a core on the other socket between t0 and its push, the interval would hold a hop the program never meant to measure, at two to three times the cost. None of these raises an error, and every one prints a number with three significant figures.

Seeing it

Five commands show what clock a machine has and how the kernel uses it:

grep -o 'constant_tsc\|nonstop_tsc' /proc/cpuinfo | sort -u   # both: an invariant TSC
cat /sys/devices/system/clocksource/clocksource0/current_clocksource      # tsc
cat /sys/devices/system/clocksource/clocksource0/available_clocksource    # the others
sudo dmesg | grep -i -e tsc -e clocksource       # frequency, refinement, any warp
grep -e vdso -e vvar /proc/self/maps             # the kernel's pages in a process

The first should print both flags; without them raw ticks are not a time. The second should print tsc; anything else means Instant::now() may be a system call. The third lists the fallbacks. The fourth shows the TSC frequency, its refinement (absent where /proc/cpuinfo shows tsc_known_freq, because the processor or hypervisor supplied the frequency), and then clocksource: Switched to clocksource tsc or a line marking the TSC unstable. The last shows the [vvar] and [vdso] mappings in grep’s own address space; every process has them. strace -f -e trace=clock_gettime on a program that calls Instant::now() in a loop prints nothing when the vDSO answers and one line per call when it falls back to the kernel.

Then measure the clock itself. Pinned with taskset -c 3, this reads it ten million times in back-to-back pairs:

use ch07_capstone::{calibrate, now, now_cpu};
use hdrhistogram::Histogram;

fn main() {
    let tpn = calibrate();                                  // ticks per ns
    println!("TSC {:.0} MHz", tpn * 1000.0);
    let mut h = Histogram::<u64>::new_with_bounds(1, 1_000_000_000, 3).unwrap();
    let (_, cpu0) = now_cpu();
    for _ in 0..10_000_000 {
        let a = now();
        let b = now();
        h.saturating_record(b - a);                         // ticks, not ns
    }
    let (_, cpu1) = now_cpu();
    for (name, q) in [("p50", 0.50), ("p99", 0.99), ("p99.9", 0.999), ("max", 1.0)] {
        let t = h.value_at_quantile(q);
        println!("{name:>6} {t:>8} ticks {:>9.1} ns", t as f64 / tpn);
    }
    println!("n {} on cpu {cpu0} then {cpu1}", h.len());
}

Predict first: a p50 of 70–100 ticks at 3.4 GHz, 20–30 ns, and a p99 within 10–20% of it, since almost nothing varies between two reads; replace now() with a bare _rdtsc() and the p50 falls to 20–40 ticks. The max is whatever else happened to the core in those ten million pairs, an interrupt or a tick of the kernel’s timer, tens to hundreds of microseconds on a core that is not isolated. The p50 is the figure to subtract from every interval the clock closes. A frequency printed far from the boot log’s says the calibration is wrong; two different CPU numbers say the pinning is.

Read more: the Intel 64 and IA-32 Architectures Software Developer’s Manual, Volume 3, describes the time stamp counter, the invariant TSC, IA32_TSC_ADJUST and TSC_AUX, and Volume 2 gives RDTSC, RDTSCP and LFENCE with their ordering rules. The Linux kernel’s documentation on timekeeping, “Clock sources, Clock events, sched_clock() and delay timers” (Documentation/timers/timekeeping.rst in the kernel source), explains what a clocksource is and how the kernel chooses one. The vdso(7) manual page lists the functions the vDSO provides on each architecture and how a process finds them.