projects02 / 06 · developer frameworks

Latte

Nanosecond latency profiler: raw TSC timestamps into per-thread ring buffers.

FrameworkProfilingC++Asm
Status
Maintained
Length
11 min read

Latte live frame latency (wasm, C++20)

loading wasm module...

Latte is a single-header C++17 telemetry framework built for measurements the act of measuring would normally destroy: scopes are timestamped with raw x86_64 TSC reads into per-thread, lock-free ring buffers, so sampling costs tens of cycles, never blocks another thread, and every statistic is deferred to a cold path after the run.

Latte started the day std::chrono stopped being an answer. I was timing order flow in a trading simulation, events living in the hundreds of nanoseconds; a single now() call runs about 150 cycles and I needed two per measurement, on paths sometimes cheaper than one. At that scale the tool's overhead isn't noise around the signal; it is the signal. Everything else I evaluated hashed strings or bumped shared counters on the hot path, so measuring thread A could slow down thread B. So I built Latte. The rest of this post is how it works, what it costs, and what broke along the way.

01How it works

The design splits into a hot path that only writes, and a cold path that does all the thinking exactly once, after sampling has stopped. Every expensive operation (aggregation, sorting, statistics, outlier filtering) lives on the cold side of that line.

Reading the clock without the clock lying

The foundation is the x86 timestamp counter, and the non-obvious part is that reading it correctly is a spectrum, not a single instruction. RDTSC reads the TSC with no ordering guarantee: on an out-of-order core, instructions from before or after the read can execute around it, which is irrelevant when timing a millisecond loop and fatal when timing a 40-cycle snippet. RDTSCP waits for all prior instructions to retire before reading: a partial guarantee. Full serialization, where nothing on either side of the read can be reordered across it, requires pairing RDTSCP with an explicit LFENCE. This is the exact territory covered in Intel's whitepaper on benchmarking code execution, and it's why Latte exposes three modes instead of one:

ModeInstructionsOrdering guaranteeMeasured Start+Stop cost
Fast__rdtsc()none60.1 cycles
Mid__rdtscp()prior instructions retire first119.8 cycles
Hardlfence + __rdtscp() on both endsfull serialization175.8 cycles

The mode is chosen per call site, and Start and Stop modes can even differ on one scope; the per-thread stack records which mode captured each timestamp, and calibration later keys on the (start_mode, stop_mode) pair. Fixing a single mode globally would either waste serialization cost everywhere (always Hard) or let reordering smear the short measurements (always Fast).

cpp
void ProcessOrder() {
    Latte::Fast::Start(__func__);   // ~30 cycles: one rdtsc + stack push
    // core logic
    Latte::Fast::Stop(__func__);    // ~30 cycles: rdtsc, pop, delta -> ring buffer
}

Scope identity without hashing

Most profilers key scopes by string content, which means hashing the name on every sample: pure hot-path waste, plus a possible allocation if the name is dynamic. Latte keys on the pointer instead. A string literal like "Physics_Engine" occupies a fixed address in the data segment, so every call with that literal resolves to the same 64-bit key with zero character comparisons. Per-thread storage is std::map<const char*, RingBuffer>: lookup is O(log N) pointer compares over the distinct IDs on that thread, no strcmp, no hash function anywhere.

The corollary is a hard correctness rule: IDs must be pointer-stable. String literals and static const char[] arrays work; a temporary std::string::c_str() or a stack buffer silently breaks identity, because the same logical name can arrive at a different address on the next call and fragment one scope into several buffers.

Per-thread storage and cache-line discipline

Each thread records into thread_local storage: its own stack, its own map, its own ring buffers. The first Start(id) on a thread allocates that ID's ring buffer entry; every subsequent call is allocation-free and lock-free. There is no atomic, no mutex, and no shared cache line anywhere on the sampling path, so a measurement on one thread cannot stall another by construction.

Layout inside the buffers matters just as much as ownership. Two logically unrelated variables landing on the same 64-byte cache line will ping-pong that line between cores on every write: the false sharing failure mode laid out in Drepper's "What Every Programmer Should Know About Memory". Latte's ring buffers are alignas(64) so each owns its cache lines outright, and internally use a Structure-of-Arrays layout (timestamps contiguous in their own array rather than interleaved with metadata) so that reading timing data pulls only timing data into L1.

Buffers are fixed at 65,536 samples per ID per thread (1 << BUFFER_PWR, power-of-two mandatory), and writes overwrite unconditionally: head = (head + 1) & BUFFER_MASK, no zeroing, no bounds branch. The mask trick is why the capacity must stay a power of two: wraparound is a single AND instead of a modulo.

Two-phase recording

Nothing aggregates during execution. Start() pushes ID, timestamp, and mode onto a per-thread SoA stack (64 slots deep, supporting nested scopes without linear search); Stop() pops, computes the cycle delta, and writes it into the flat ring buffer. That's the entire hot path. Profilers that maintain running means or histogram buckets pay map-traversal and cache-miss costs on every sample for statistics nobody has asked for yet; Latte defers all of it to a single cold-path call.

The cold path forks into two outputs. DumpToStream() is the reporting route: it walks every thread's storage, runs the outlier filter, computes per-scope statistics (mean, median, stddev, skewness, min/max/range), applies self-offset calibration, and writes formatted tables to any std::ostream. Snapshot(id) is the raw route: it returns the uncleaned std::vector<Cycles> for one ID aggregated across threads, for when you want the distribution itself (to plot a histogram or feed your own analysis) rather than a summary.

Filtering scheduler noise without eating the tail

Any real run collects a handful of samples poisoned by preemption: the thread gets scheduled off-core mid-measurement and a 200 ns event records as 100 us. A naive mean is destroyed by one of these. But a plain IQR filter over raw samples over-corrects in the other direction, because latency distributions are legitimately right-skewed and the tail is often the part you care about most.

Latte's cleaning pass splits the difference: samples are bucketed in groups of 1,000, the maximum of each bucket is recorded, and the IQR cutoff is computed over those bucket maxima rather than the raw samples. Genuine scheduler spikes stand out sharply against bucket maxima; the legitimate tail shape does not. Samples above the cutoff are counted (reported in the OUTLIER column) and excluded; everything else feeds the statistics.

02Trade-offs

Nothing here is free: the cost just moves off the hot path and lands somewhere else, and it's worth being explicit about where.

ChoseGave upWhy it held
direct rdtsc/rdtscp/lfence access, lowest possible read costportability (x86_64 only, GCC/Clang constructs)the target systems are x86_64; an abstraction layer would cost the cycles the project exists to save
zero hashing, zero strcmp on the hot pathflexible identifierspointer-stable literals are a workable discipline in instrumented code
lock-free, atomic-free samplingconcurrent reportingreports happen once at the end anyway; a barrier is cheaper than a lock on every sample
fixed, predictable memory (overwrite ring)unbounded historythe most recent 65,536 samples per scope is enough for distribution analysis
one less compare per sampleStop(id) validationLIFO discipline is enforceable by convention; see below for how that bites

03Benchmarks

Setup: AMD Ryzen 5 7600X (6 cores, 4.7 GHz base / 5.3 GHz boost), g++ -O3 -march=native, pinned core, 100,000 iterations per trial, 100 independent trials, one warm-up batch to stabilize branch predictors and caches. Everything measured in cycles via the TSC itself, which sidesteps the measurement-bias problem from the intro: the probe and the subject are the same clock.

One correction matters before reading the chart. Latte's numbers are Start+Stop pairs, two reads, because timing a region inherently takes two timestamps, while the raw intrinsics were benchmarked as single calls. Comparing a pair against a single read makes Latte look artificially expensive, so the chart doubles __rdtsc and __rdtscp (mean x2, std dev x sqrt(2), since the spread of a sum of two independent samples grows with the square root, not linearly). That's the honest baseline: two back-to-back raw reads is what you'd write by hand without the library. lfence and std::chrono::now remain single-call costs: lfence produces no timestamp and is never used alone, and chrono is shown at its native per-call price. Bars are sorted by latency.

The sorted view makes the real story visible: each Latte mode lands essentially on top of its doubled raw primitive. Fast at 60.1 cycles against two raw __rdtsc reads at 60.2: the framework's stack push, pop, delta, and ring-buffer write add effectively nothing beyond the two reads it must do anyway. Mid at 119.8 sits ~4 cycles above two __rdtscp reads at 115.4. Hard at 175.8 is the only mode with visible framework cost, and most of that is the four fence/read instructions it deliberately executes. Meanwhile a complete Fast measurement (both timestamps, stored) costs less than a single std::chrono::now() call at 153.9. At the 7600X's 5.3 GHz boost clock (0.213 ns per cycle), that's roughly 13 ns of self-overhead per measured region.

Here's the calibrated output against a small simulated trading pipeline, with self-offset correction applied and the IQR pass already counting outliers:

#==============================================================================================================#
| LATTE TELEMETRY [TIME][CAL]                                                                                  |
#==============================================================================================================#
| SELF-OFFSET H[Start] x W[Stop]                                                                               |
|                        F             M             H                                                         |
| F                0.21 ns      10.02 ns      10.02 ns                                                         |
| M                0.21 ns      10.02 ns      10.02 ns                                                         |
| H                0.21 ns      10.02 ns      10.02 ns                                                         |
| PULSE           10.02 ns                                                                                     |
|--------------------------------------------------------------------------------------------------------------|
| COMPONENT             SAMPLES       AVG    MEDIAN   STD DEV    SKEW       MIN       MAX     RANGE    OUTLIER |
|--------------------------------------------------------------------------------------------------------------|
| DP_Build_Total              1   38.07 s   38.07 s   0.00 ns    0.00   38.07 s   38.07 s   0.00 ns         0  |
| DP_StateLoop            65536  31.15 us  30.96 us   1.42 us   12.13  29.32 us  95.10 us  65.78 us         0  |
| Sim_Tick_Total           4997 226.79 ns 220.42 ns  76.04 ns    1.40 110.21 ns 821.55 ns 711.34 ns         3  |
| Sim_OrderFlow            4997  43.62 ns  29.63 ns  36.61 ns    2.02   9.59 ns 380.51 ns 370.91 ns         3  |
| Sim_AskLoop              1216   1.03 us 711.34 ns   1.06 us    2.14   0.00 ns   8.30 us   8.30 us         0  |
| Sim_BidLoop              1247   1.12 us 751.42 ns   4.21 us   32.56   0.00 ns 145.96 us 145.96 us         0  |
| Sim_RiskPnL              5000   6.24 ns   9.59 ns   4.67 ns   -0.57   0.00 ns  19.82 ns  19.82 ns         0  |
#==============================================================================================================#

The SELF-OFFSET table at the top is what makes the rest trustworthy: it's the measured cost of Start and Stop called back-to-back with nothing between them, broken down by every mode pairing, and it's what gets subtracted per-sample in calibrated mode. That's why Sim_BidLoop's skew of 32.56 and Sim_Tick_Total's three outliers are readable signal instead of being buried under the instrumentation's own cost.

04Where it went sideways

Two of the sharpest lessons ended up written directly into the correctness rules, and both trace back to the same design decision.

The first: Stop(id) doesn't validate its argument against the top of the stack. It always pops the most recent Start(), strictly LIFO, whatever ID you hand it. Cross two nested scopes' Start/Stop calls (trivially easy during a refactor that splits one timed region into two) and nothing crashes, nothing asserts. One scope's time gets silently attributed to the other's ID, and the only symptom is a component's statistics looking subtly off in a report you may not read closely. Validating on every Stop() would have meant a compare on the hot path for a mistake the type system can't prevent anyway, so the check was deliberately left out, which converts "pass matching IDs" from a style suggestion into a contract the caller has to actually honor.

The second: DumpToStream() and Snapshot() are genuinely unsafe to call while any thread is still sampling: not slow, not approximate, undefined behavior. The manager's mutex protects only the global list of per-thread storage pointers; the ring buffers and history maps themselves are written with no locks and no atomics, on purpose, because that's where the speed comes from. Call DumpToStream from a reporting thread while a worker is mid-Start and you have a data race. The fix isn't synchronization, it's sequencing: join the workers, or hold a barrier guaranteeing no Start/Stop/LATTE_PULSE is in flight, before reporting.

Both sharp edges are the same trade viewed twice: correctness checks that would normally live inside the library got pushed out to the caller, because keeping them inside would mean paying for them on every sample instead of once, at the boundary where they belong.

05What I'd do better next time

Having built this, the thing I understand now that I didn't at the start is that the hard problem was never reading the clock: Intel documented that fifteen years ago. The real constraint was refusing to let convenience creep back onto the hot path, one small compromise at a time: one validated ID here, one shared counter there, each individually cheap and collectively the reason every existing profiler was too slow for the job. The two-phase split wasn't a feature; it was a line I had to keep defending against my own instincts.

The next version starts from that understanding rather than arriving at it. The fixed constants (65,536-sample buffers, 1,000-sample IQR buckets) would become compile-time parameters, since the right sizes are workload-dependent and the current ones just encode my workload. MSVC support means conditionally wrapping the GCC/Clang attributes the header leans on. And an ARM port through CNTVCT_EL0 is the interesting open problem: the generic timer has a completely different ordering story from RDTSC/RDTSCP, so the Fast/Mid/Hard split wouldn't translate; it would have to be rederived from ARM's memory model, which is exactly the kind of investigation the profiling work here now makes it possible to do honestly: I finally have a measurement tool cheap enough to measure itself.

06Further reading