--- 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: ```c 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.