Profiling the hot path

"Where does the time go on average?" and "why was this one message slow?" are different questions.

Sampling profilers answer the first. perf record interrupts the program thousands of times a second and records the call stack each time. Functions on the stack in many samples are where the time goes. The overhead is low and no code changes are needed.

Tracing and instrumentation answer the second. You record timestamps at chosen points for every event, then look at the slow events individually.

The question is about the tail, so a sampling profile on its own is the wrong first tool: the p99.9 events are one in a thousand, so they are a tiny share of samples, drowned by the common case.

Still, the profile is where to start for a regression in the body, and its output is worth reading well.

perf record -F 9999 -g --call-graph dwarf -p <pid> -- sleep 30
perf report                       # or: perf script | stackcollapse-perf.pl | flamegraph.pl > out.svg

A flame graph draws each stack sample as a column of boxes from the outermost function at the bottom to the innermost at the top, merges identical stacks, and sorts alphabetically. Width is the fraction of samples; height is stack depth. Look for wide plateaus at the top: functions that are themselves busy. Compare before and after a release with a differential flame graph.

Practical points:

• Build with frame pointers (-fno-omit-frame-pointer) or use DWARF unwinding, or the stacks will be broken.
• Inlined functions disappear into their callers; perf report --inline and debug info recover some of them.
• A spinning thread polling an empty queue shows its polling loop as hot. That is waiting, not work; profile under real load or filter it out.

To explain individual slow events, record what happened to each one:

struct Trace { std::uint64_t seq; std::uint32_t t_rx, t_decoded, t_booked, t_decided, t_sent; };
// on the hot thread: t = rdtsc-based timestamps at each stage, pushed into a ring

Every message gets a fixed-size record of stage timestamps, pushed through a lock-free ring to a recorder (Module 4). Offline, select the slowest 0.1% and compare them with typical ones: which stage grew? Was it the same instrument, the same message type, the first message after an idle period, a burst? Did it coincide with a page fault, a context switch or an interrupt on that core, which kernel tracing (perf trace, ftrace, bpftrace) can record with timestamps on the same clock?

That correlation is how the tail is explained: "the slow book updates are all the first update to a price level not touched in the last few seconds, and they miss in L3" is a finding; "the profile looks the same" is not.

• perf stat for counters over a run (next lesson).
• Intel VTune and AMD uProf for vendor-specific detail, microarchitecture analysis and memory access views.
• Off-CPU analysis (perf sched, offcputime from BCC) shows where threads wait rather than run: on locks, I/O, the scheduler.
• Intel Processor Trace records every branch taken with very low overhead, so the exact path of one slow event can be reconstructed afterwards. It produces large amounts of data and is a specialist's tool, but it is the closest thing to replaying a single slow message.

I would not start with a sampling profile, because p99.9 events are one in a thousand samples and won't show. I would use per-message stage timestamps to see which stage grew in the slow events and what they have in common, and correlate them with kernel events on that core. If the slow stage is the book update, I'd then profile or microbenchmark that path on inputs like the slow ones, and diff against the previous release.