Latency Measurement & Profiling in C++

TL;DR

Mean latency is a lie. HFT systems care about P99 and P99.9 — the tail latency that determines worst-case execution. Use rdtsc for sub-nanosecond timing, HDR histograms for distribution tracking, and perf/VTune for identifying hot paths. Never measure under profiling — profile separately, measure in production.

Why mean latency is misleading

cpp

Godbolt

Latency samples (µs): 1, 1, 1, 1, 1, 1, 1, 1, 1, 100

Mean:   10.9 µs  ← looks fine
P50:    1 µs     ← fine
P99:    100 µs   ← 100× worse than expected!
P99.9:  100 µs

In HFT, the P99 is what loses money. An order that should have gone out at 1µs but took 100µs due to a GC pause (from a Java backend) or kernel preemption is a missed trade.

Timing with rdtsc

rdtsc (Read Time Stamp Counter) counts CPU cycles — the most precise timer available, with ~1ns resolution on modern CPUs.

cpp

Godbolt

#include <cstdint>
#include <x86intrin.h>  // or <intrin.h> on MSVC

// Read current timestamp
inline uint64_t rdtsc() {
    return __rdtsc();
}

// Serializing variant — prevents instruction reordering across the measurement
inline uint64_t rdtscp() {
    uint32_t aux;
    return __rdtscp(&aux);
}

// Convert cycles to nanoseconds
// Measure your CPU's TSC frequency first
constexpr double TSC_GHZ = 3.0;  // CPU speed in GHz

double cyclesToNs(uint64_t cycles) {
    return static_cast<double>(cycles) / TSC_GHZ;
}

// Usage
uint64_t start = rdtsc();
processMarketData(update);
uint64_t end = rdtsc();
uint64_t latency_cycles = end - start;
double latency_ns = cyclesToNs(latency_cycles);

Getting TSC frequency

bash

# From kernel
cat /sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_max_freq

# From dmesg (TSC-invariant CPUs)
dmesg | grep "TSC"

# Calibrate in code
uint64_t calibrateTSC() {
    auto t0 = std::chrono::steady_clock::now();
    uint64_t c0 = rdtsc();
    std::this_thread::sleep_for(std::chrono::milliseconds(100));
    uint64_t c1 = rdtsc();
    auto t1 = std::chrono::steady_clock::now();
    auto ns = std::chrono::duration_cast<std::chrono::nanoseconds>(t1 - t0).count();
    return (c1 - c0) * 1'000'000'000ULL / ns;
}

`clock_gettime` — the POSIX alternative

cpp

Godbolt

#include <time.h>

uint64_t nowNs() {
    struct timespec ts;
    clock_gettime(CLOCK_MONOTONIC_RAW, &ts);
    return ts.tv_sec * 1'000'000'000ULL + ts.tv_nsec;
}

// CLOCK_MONOTONIC_RAW: no NTP adjustments, ~20-30ns overhead
// CLOCK_MONOTONIC:     NTP-adjusted, same overhead
// CLOCK_REALTIME:      Wall clock, can jump backwards
// CLOCK_TAI:           Leap-second aware, needs kernel config

clock_gettime has ~20-30ns overhead per call. For sub-100ns measurements, use rdtsc.

HDR Histogram — tail-latency tracking

HdrHistogram tracks the full distribution with configurable precision:

cpp

Godbolt

// hdr_histogram (C library, C++ wrappers available)
// https://github.com/HdrHistogram/HdrHistogram_c

#include <hdr/hdr_histogram.h>

hdr_histogram* hist = nullptr;
// Track values from 1 to 60,000,000 ns (1ns to 60s), 3 significant figures
hdr_init(1, 60'000'000, 3, &hist);

// Record measurements
hdr_record_value(hist, latency_ns);

// Report percentiles
printf("P50:   %lld ns\n", hdr_value_at_percentile(hist, 50.0));
printf("P99:   %lld ns\n", hdr_value_at_percentile(hist, 99.0));
printf("P99.9: %lld ns\n", hdr_value_at_percentile(hist, 99.9));
printf("Max:   %lld ns\n", hdr_max(hist));

// Print full histogram
hdr_percentiles_print(hist, stdout, 5, 1.0, CLASSIC);
hdr_close(hist);

Simple rolling histogram in C++

cpp

Godbolt

#include <array>
#include <atomic>
#include <algorithm>
#include <numeric>

template<size_t N = 1024 * 1024>
class LatencyHistogram {
public:
    void record(uint64_t ns) {
        size_t bucket = std::min(ns / 100, N - 1);  // 100ns buckets
        ++counts_[bucket];
        ++total_;
    }

    uint64_t percentile(double p) const {
        uint64_t threshold = static_cast<uint64_t>(total_ * p / 100.0);
        uint64_t cumulative = 0;
        for (size_t i = 0; i < N; ++i) {
            cumulative += counts_[i];
            if (cumulative >= threshold)
                return i * 100;  // bucket midpoint in ns
        }
        return (N - 1) * 100;
    }

    void reset() {
        counts_.fill(0);
        total_ = 0;
    }

private:
    std::array<uint64_t, N> counts_{};
    uint64_t total_ = 0;
};

Profiling tools

perf — system-wide profiler

bash

# CPU cycles breakdown
perf stat -e cycles,instructions,cache-misses ./app

# Find hot functions (sampling)
perf record -F 10000 ./app  # 10kHz sampling
perf report --sort=symbol --percent-limit 1

# Annotate source with hotspot lines
perf annotate processOrder

# Flamegraph
perf record -g ./app
perf script | stackcollapse-perf.pl | flamegraph.pl > flame.svg

Isolating the critical path

bash

# Disable CPU frequency scaling (prevents latency spikes)
echo performance | sudo tee /sys/devices/system/cpu/cpu*/cpufreq/scaling_governor

# Disable turbo boost (consistent timing)
echo 1 | sudo tee /sys/devices/system/cpu/intel_pstate/no_turbo

# Pin process to CPU 3 (isolated from OS tasks)
taskset -c 3 ./app

# Real-time priority (requires privileges)
sudo chrt -f 99 ./app

Latency spike investigation

cpp

Godbolt

// Detect latency spikes in a tight loop
uint64_t prev = rdtsc();
while (running) {
    processMessage();
    uint64_t now = rdtsc();
    uint64_t delta = now - prev;
    if (delta > 10000) {  // >3.3µs spike at 3GHz
        logSpike(delta, getStackTrace());
    }
    prev = now;
}

Common spike sources:

OS interrupts (IRQ affinity — move them off the critical core)
TLB shootdowns (huge pages help)
NUMA migrations (pin to one node)
Memory allocation in hot path (pre-allocate everything)
Kernel preemption (use SCHED_FIFO)

What to measure

Metric	Tool	Target
Per-message latency	rdtsc	P99 < 5µs
Function call overhead	rdtsc + histogram	`< 100ns`
Cache miss rate	perf stat	< 1% L1 miss rate
Branch mispredictions	perf stat	< 0.5% rate
System call overhead	strace -T	0 on hot path
Interrupt latency	/proc/interrupts	IRQs on non-critical cores