lttng-tracing-root-cause-analysis

name

lttng-tracing-root-cause-analysis

description

Methodology for root-causing hard concurrency / memory-ordering bugs (intermittent races, use-after-free, RCU/lock-free publish-order defects, "impossible" stale reads) with LTTng flight-recorder (snapshot) tracing — when static analysis, printf, and a debugger all fall short. Covers the snapshot+violation+abort setup, tracepoint instrumentation discipline (why tracepoints not printf), how to enrich a violation event so the trace is self-diagnosing, and the trace-reading patterns that crack these bugs (notably: a stale-after-write "paradox" is a happens-before gap, not a timing bug).

LTTng flight-recorder root-cause analysis

When a concurrency bug is intermittent and the assertion fires deep in a hot path, the three usual tools fail in three different ways:

• Static reading can't tell you the interleaving that actually happened.
• printf perturbs the timing — the µs-scale window you're hunting often vanishes when you add I/O — and floods you with output from the wrong threads.
• A debugger stops the world; the race won't reproduce under a breakpoint, and you can't single-step a 192-thread interleaving.

LTTng flight-recorder (snapshot) mode is the tool that fits: near-zero overhead ring buffers per CPU, a global high-resolution clock so events from different CPUs are comparable, and an on-demand dump of exactly the window leading up to the failure. You instrument the culprit to fire a violation tracepoint, dump the snapshot, and abort; then you read the last events before the abort and the interleaving walks you to the cause. This is the tool of last resort for concurrency bugs — reach for it once you've ruled out the cheap explanations.

The setup: snapshot + violation + abort

1. Flight-recorder (snapshot) session, small per-CPU buffers. Snapshot mode keeps a rolling overwrite buffer in memory and only writes to disk when you ask. Start small so the dump is a tight window around the failure:

   lttng create mysess --snapshot
   lttng enable-channel --userspace --subbuf-size=64K --num-subbuf=4 ch
   lttng enable-event   --userspace --channel ch 'myprovider:*'
   lttng start
   

   64 KiB/CPU is the CLAUDE.md default, and small is right for two reasons, not one: (a) the dump is a tight window around the failure, so it decodes fast and you read only the relevant events; (b) — the one that actually matters for reproducing the bug — a 64 KiB ring stays resident in L2, so the tracepoint stores don't evict the working set into L3/DRAM. A large (multi-MiB) ring pollutes the cache and perturbs the very µs-scale race window you're hunting; the bug can stop reproducing under heavy tracing for the same reason it stops under printf. Keep the ring small to keep the timing faithful. If your per-step tracepoints (below) are high-rate and the interesting window scrolls out before the violation, FIRST cut the event rate — disable the flooding per-iteration event and recover its data another way (e.g. from a core, or a single enriched violation event) — and only bump the subbuf size as a last resort (e.g. 256K × 4 = 1 MiB/CPU), as little as you need; a bigger buffer means both more events to read and more timing disturbance.

2. Emit the violation from the culprit, then snapshot, then abort. At the exact check that detects the corruption, fire an enriched tracepoint, persist the in-memory ring, and crash so nothing overwrites the window:

   if (corruption_detected) {
       FT_TP(violation, /* discriminating state — see below */);
       (void) system("lttng snapshot record 1>&2");
       abort();
   }
   

   Gate all of this behind a build flag (e.g. -DFT_ENABLE_TRACING) so it compiles out of production and your normal test matrix.

3. Read the window:

   lttng stop
   babeltrace2 ~/lttng-traces/mysess-*/ > trace.txt
   

Instrumentation discipline

• Tracepoints, never printf — timing matters. The bug lives in a sub-microsecond window; printf's I/O perturbs it out of existence and serializes threads. Tracepoint emission is a few hundred ns into a lock-free per-CPU buffer.

• Make the violation event self-diagnosing. Don't just record "it failed" — record the state that discriminates between hypotheses. For a bad pointer, the high-value fields are usually:

  • the object's identity and a round-trip check (e.g. resolve the object by its own back-reference and compare): if it round-trips to itself the object is valid; if not, it's recycled / stale memory. This one field instantly separates "use-after-free of recycled memory" from "valid object, wrong links."
  • liveness counters (child count, refcount): zero/garbage ⇒ freed.
  • the relevant back-pointers (parent, prev) so you can see which links were and weren't wired.

  These let you classify the failure from the violation event alone, before you even read the surrounding window.

• Add enter/step tracepoints to follow the algorithm. One tracepoint at the entry of the suspect routine and one per iteration of its core loop (carrying the loop variables) reconstruct the control flow that reached the violation — you see the path, not just the endpoint.

• Mind the LTTNG_UST_TP_ARGS limit. lttng-ust caps a tracepoint at ~10 argument pairs. Exceed it and you get a cryptic macro error like unknown type name 'LTTNG_UST__TP_EXPROTOconst' (the arg-count machinery ran off the end). Keep a violation event ≤ ~8 fields; drop redundant ones (e.g. a field that's always NULL at the violation, or one a round-trip already implies). Pointer fields use lttng_ust_field_integer_hex(uintptr_t, name, (uintptr_t) val); counters use lttng_ust_field_integer(...).

Reading the trace — the patterns that crack it

• Read the full window, all CPUs, with ns timestamps and raw addresses. Then grep by address to pull every event touching the culprit object(s) across all threads, in time order. This reconstructs the cross-thread interleaving that no static reading could show. Note the cpu_id on each event to separate the writer thread from the reader thread.

• Distinguish trace markers from the actual memory operation. A tracepoint at a function's entry fires before the store inside it. Don't read the tracepoint timestamp as the store's timestamp — find the event that corresponds to the real rcu_assign / publish (often a different, later marker). Mis-attributing the store's time sends you chasing ghosts.

• THE key pattern — the stale-after-write "paradox" is a happens-before gap, not a timing bug. If the trace shows a field written at time T and read stale at T+Δ on the same object with no intervening write anywhere, that is not a contradiction and not "the store didn't land yet" (Δ can be microseconds). It means the reader reached that field through a pointer that was published before the field's store, so there is no release-consume edge carrying the store to the reader — the stale read is legal at any wall-clock delta. Treat the paradox as a signal: find which earlier publish anchored the reader's data-dependency (consume) chain, and you've found the mis-ordered publish. The fix is to publish the field before the pointer that lets readers reach it (see the rcu-mutation skill: wire back-pointers before the forward/back-channel publish; fresh edges before the live re-parent edge).

• Walk backwards from the abort. The violation event is the last thing in the buffer. The few events just before it — on any CPU — are the proximate cause. Follow the addresses upward until the picture is consistent.

After you've found it

• Strip the temporary enter/step/violation tracepoints and the system("lttng snapshot record") + abort() from the code before committing (they were scaffolding; the build flag kept them out of the matrix, but don't leave dead diagnostic noise in the source). Keep the durable, low-rate tracepoints if they have ongoing value.
• A correct invariant you discovered while instrumenting may deserve to become a permanent assertion / verify-pass — but only commit it once the code actually satisfies it, or it turns the tree red on a pre-existing, non-destructive gap (scope it as separate work).

Worked example (userspace-rcu fractal trie — holder != NULL)

Symptom: an ordered-traversal reader intermittently hit assert(holder != NULL) in an up-walk (ft_skip_reanchor) under empty→rebuild churn — ~88% repro, but no static reading found it.

1. Added a reanchor_violation tracepoint (the reached node, a round-trip metadata_to_item check, its child count, and the relevant back-pointers) + reanchor_enter/reanchor_step to follow the up-walk, all behind -DFT_ENABLE_TRACING; snapshot + abort on the violation.

2. The violation event alone said: round-trip == self (so valid, not recycled), child-count == 1 (live), back-pointer set — yet parent == NULL. So: a valid, live node, reachable, with an unwired parent.

3. The paradox: the writer set that node's parent at T, the reader read NULL at T+2.3µs, same metadata object, no intervening write. → happens-before gap.

4. The full window (grepping the node's address across CPUs) showed the writer publishing a recompacted cluster into the live tree by setting a live re-parented child's back-pointer (a back-channel publish) before wiring a fresh sibling child's parent. The reader entered via the live child, so its consume chain anchored before the fresh-parent store → legal stale NULL.

5. Fix: at publish, wire the fresh edge (and the cluster top's own back-pointer) first and the live re-parent edge last. ~88% failure → 0/96.

LTTng didn't just confirm a hypothesis — the enriched violation event and the all-CPU window generated the explanation that static analysis had missed.