From: Ondřej Surý Date: Tue, 7 Jul 2026 14:51:55 +0000 (+0200) Subject: Add the lttng-tracing-root-cause-analysis agent skill X-Git-Url: http://git.ipfire.org/gitweb/?a=commitdiff_plain;h=1d0af73cd7a2bd8e9b6d370fd4ac2f5bca993703;p=thirdparty%2Fbind9.git Add the lttng-tracing-root-cause-analysis agent skill Describe the LTTng flight-recorder methodology for concurrency bugs that static reading, printf and debuggers all miss: small snapshot buffers to keep timing faithful, a self-diagnosing violation tracepoint followed by snapshot-and-abort, and the trace-reading patterns — notably that a stale-read-after-write "paradox" indicates a missing happens-before edge, not a timing problem. --- diff --git a/.agents/skills/lttng-tracing-root-cause-analysis/SKILL.md b/.agents/skills/lttng-tracing-root-cause-analysis/SKILL.md new file mode 100644 index 00000000000..6bed4242e42 --- /dev/null +++ b/.agents/skills/lttng-tracing-root-cause-analysis/SKILL.md @@ -0,0 +1,182 @@ +--- +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.