Debugging Concurrent Code

Part I · Module 26 · Chapter 26.9 · Debugging Concurrency

1. Why the Method From Module 25 Does Not Transfer

Chapter 25.5 built a method: reproduce the failure, form a hypothesis that can be wrong, ask the program, narrow. Every step of it assumes the failure is a function of the input.

A concurrency bug is a function of the input and the schedule — which thread ran when, which core it ran on, what else the machine was doing. The schedule is not an input you control, not recorded anywhere, and not reproducible on request. Three consequences follow, and all three are measured in this module.

The same binary with the same input fails sometimes. Chapter 26.5 §3's deadlock fired 0 times in 100 trials in one configuration and 100 times in 100 in another, with no change to the code.

Observing it changes it, which is §2 and the reason this chapter exists.

And a passing run is not evidence. Chapter 26.3's §7 callout made the full argument: the width of a race window is a property of the generated code, so a test that passes a thousand times has established something about a binary, not about a program.

So the techniques in this chapter are not "Module 25 but harder". They are a different set, chosen because they do not depend on reproducing anything.

2. The Observer Effect, Measured

Here is the thing everyone does first: add a print statement and watch. Four threads, 50,000 racy increments each, expecting 200,000 — once with nothing added, once with an fprintf per iteration, once with an atomic increment per iteration:

  four threads, 50000 increments each, expecting 200000
    rep 1: no instrumentation  … | fprintf per iteration  … | atomic per iteration   …

Twenty-one repetitions:

The fprintf arm nearly fixed the bug. A loop losing 45.6% of its updates lost 0.5% once it was printing, and the range tightened to 196,908–199,916 — reliably almost-correct. The race is still there; the window closed, because each iteration now spends far longer doing I/O than it spends in the unprotected read-modify-write, so the chance of two threads overlapping in that tiny span collapses.

Which is the single most important fact about debugging concurrency: the diagnostic removes the symptom. You add a print to find out what is happening, the failure rate drops a hundredfold, and you conclude either that you have fixed it or that it is "intermittent". Both conclusions are wrong and the second one is how these ship.

The third arm is reported honestly because it is not tidy. Adding an atomic increment per iteration gave a median of 104,928 — essentially the un-instrumented rate — but a range spanning 71,044 to 199,076, which means on some runs it closed the window completely and on others not at all. So the correct statement is that it is unstable, not that it has no effect. If I had run it three times and seen 199,076 I would have concluded that any instrumentation closes the window; if I had seen 71,044 three times I would have concluded that only I/O does. Twenty-one reps say neither.

The practical rules that follow:

Never conclude anything from a run with a print statement added. Measure the rate with and without, over many trials, before you believe a change did anything.

Prefer instrumentation that does not block: a per-thread counter in memory, dumped after join, rather than a write per iteration. It still perturbs — everything does — but by nanoseconds rather than microseconds.

And prefer the tools in §4 that do not need the bug to happen at all.

3. Reproduction Is the Problem, So Measure a Rate

If a bug happens sometimes, the useful artefact is not a stack trace — it is a rate. Chapter 26.5 §3's table is the model: 100 independent trials per configuration, fresh state per trial, nine whole-process runs:

Three things that table does and a single run cannot.

It turns "intermittent" into a number, which makes a before-and-after comparison possible. "I fixed it, it doesn't happen any more" is unfalsifiable when the baseline was unknown.

It shows you the knobs. The configurations differ only in how the threads are started and whether there is a delay between the locks, and those two knobs move the rate from 0% to 100%. That tells you what to vary when you need the bug on demand.

And the range is the part that stops you over-claiming. The middle row ranged from 5 to 54 across nine runs. Any single run of that configuration gives a number you would have quoted as "about 40%" or "about 5%" with equal confidence.

The amplification knobs worth knowing, roughly in order of usefulness:

Put the amplified configuration in the test suite, not the natural one. A test that deadlocks 100 of 100 times with a 1 ms sleep is a regression test; the same test without the sleep passes forever and protects nothing.

4. The Tool That Reasons About the Program

Every technique so far needs the bug to happen. ThreadSanitizer does not, and that single property is why it is the most valuable instrument in this module.

Here is the sharpest demonstration. A four-thread increment of a plain long at -O2, which Chapter 26.3 §3 measured as producing the correct answer every run:

counter = 800000 of 800000  <-- CORRECT ANSWER
WARNING: ThreadSanitizer: data race (pid=…)
SUMMARY: ThreadSanitizer: data race tsanrace.cpp:5 in bump(int)

The program gave the right answer and the tool said it was broken, and the tool was right. TSan does not ask whether this run went wrong; it asks whether two accesses to one location were ordered. That is a property of the program, so the answer does not depend on the schedule you happened to get, and it does not depend on the optimiser's choice of window width.

Three practical details.

It names the file, the line and the function, so the finding is actionable — tsanrace.cpp:5 in bump(int) — and it prints both stacks, which tells you which two accesses it paired.

It exits 134, so a test harness can gate on it. Chapter 25.6 §5's warning applies: check the exit status, and check it directly rather than through a pipe, or your gate reports the status of tail.

Its instrumentation also widens the window, which is worth knowing because the numbers move: the same program that produced 800,000 un-instrumented produced 600,000 under TSan. The finding is what matters, not the instrumented program's output.

5. What It Costs, and What It Does Not Find

TSan is not free and is not complete, and both limits decide how you use it.

The cost, on correct threaded code. A mutex-protected counter, four threads, 200,000 iterations each — work the optimiser cannot delete — median of nine runs:

The ranges do not overlap, and the bound from worst-baseline to best-instrumented is 31.0×–39.3×. And TSan reported nothing on this correct program — no false positive, which is the property that makes it usable in CI at all.

A word on why that baseline is a mutex loop rather than the racy loop from §4, because the choice matters. Measuring the slowdown on the racy program gave 111× and that number is junk. At -O2 the optimiser collapsed its 800,000 increments into a single add, so the un-instrumented run is almost entirely process start-up, while the instrumented build actually executes every iteration. The ratio is therefore not "the cost of instrumentation" but "the cost of instrumentation plus the work the optimiser had deleted". You cannot measure a sanitizer's overhead on work that was optimised away — and the symptom that something is wrong is a slowdown far outside everything else you have measured.

For context, Chapter 25.6 §6 measured TSan at 16.4× on a mixed workload with a range of 402–1490 ms, and said plainly that the defensible claim is "roughly an order of magnitude or more, not a number". 36.5× on lock-per-iteration code is consistent with that, and the two together give the useful shape: the denser the synchronisation, the worse the ratio, so the number for your program has to be measured on your program.

What it does not find matters just as much:

A deadlock. Chapter 26.5 §10: a program that deadlocked every run, built with -fsanitize=thread and run with TSAN_OPTIONS=detect_deadlocks=1, produced output byte-identical to the un-sanitized run. The detector exists as a flag — help=1 lists it, defaulting to false — and on this macOS/arm64 build it reported nothing. Races and deadlocks need different tools, and here the second tool is §6.

A missing memory ordering that is still correctly synchronised. TSan finds unordered accesses, not orderings that are weaker than your algorithm needs.

Anything in a code path the run did not execute. Chapter 25.6 §5's asymmetry in full: a finding is near-certain, a clean run is not proof. So TSan belongs on the whole suite and on long realistic runs, which the 36.5× makes a scheduling decision — nightly rather than per-commit.

And it cannot be combined with ASan, so races and memory errors are separate runs.

6. Make the Invariant Checkable Instead

When the dynamic tools cannot help — a deadlock here, or any invariant TSan does not model — the strongest remaining technique is to move the check into your own code, so the thread that violates the rule reports it immediately.

Chapter 26.5 §6's levelled mutex is the worked example: every mutex has a level, each thread's current level lives in a thread_local, and a lock that is not strictly downward throws. What that buys is precisely what §3 says you cannot get from testing — the 0-of-100 configuration, where the defective code never deadlocks, becomes an exception on the first trial, attributed to the thread and line that broke the rule.

The same move generalises:

The last row deserves emphasis because it is the only one that works at compile time: clang's thread-safety analysis can check "this field is only accessed with that mutex held" statically, with no run required and therefore no schedule to get lucky with. It costs annotations on the declarations and it is the cheapest rigorous check available on this toolchain.

The general principle, which this module has reached from four directions: where the language will not enforce an invariant, arrange for violating it to produce a loud, immediate, attributable error rather than a rare wrong answer.

7. Reading a Program That Has Stopped

A hang is the easiest concurrency failure to triage, because the first measurement costs nothing and splits the space in two.

CPU at zero and not exiting: everything is blocked. A deadlock (Chapter 26.5), a lost wake-up (Chapter 26.6 §3), a join on a thread that will never finish, or a wait on a condition that nobody will make true.

CPU pinned and no progress: everybody is running. A livelock or a spin — Chapter 26.5 §9 and Chapter 26.6 §2, where a spinning wait burned 209 ms of CPU for a 200 ms wait while a condition variable used 0.1 ms.

That distinction decides which half of the module to re-read, and top or time answers it.

Then get the stacks. lldb is available on this machine — Chapter 25.7 §1's inventory — so attaching to the live process and asking for every thread's backtrace is the reliable next step:

(lldb) process attach --pid 12345
(lldb) thread list
(lldb) thread backtrace all

What you are looking for is two or more threads stopped inside a lock acquisition or a wait. For a deadlock, the cycle is usually obvious once all the stacks are on one screen: thread 2 blocked in lock called from transferAB, thread 3 blocked in lock called from transferBA. For a lost wake-up there is no cycle — one thread sits in wait and nothing else is doing anything, which is the signature.

The limits of the environment, reported rather than papered over: valgrind is absent, and sample attaches but reports an empty call graph (Chapter 25.8 §1). So the live-debugger route is the one that works here, and that is enough for a hang.

8. Logging in a Concurrent Program

Logging is the technique you will actually use most, and it has three failure modes specific to threads.

It changes the schedule, which is §2: 45.6% of updates lost became 0.5%. A log line per iteration is a synchronisation primitive you did not mean to add.

Interleaved output is not a timeline. Two threads writing to the same stream produce lines in the order the writes landed, which is not the order the events happened — and Chapter 23.1 §6's buffering means a line can sit in a buffer long after the event. Without a thread id and a timestamp on every line, the ordering you read off is fiction.

And the log itself can be the bottleneck. Chapter 22.9 measured the structure that avoids this: every thread appends to its own buffer or a queue, and exactly one writer does the I/O.

So the shape of logging that works in a threaded program:

Record per thread, in memory, and merge after join. A std::vector per thread of {timestamp, event} costs nanoseconds per entry, perturbs the schedule far less than I/O, and join gives you the happens-before edge (Chapter 26.8 §5) that makes reading all of them afterwards safe with no synchronisation at all.

Put a monotonic timestamp and a thread id on every entry, because without them you cannot reconstruct an ordering, and the ordering is the whole question.

Count, do not narrate. A per-thread counter of how many times each branch was taken answers most questions and costs almost nothing. A line per iteration answers fewer and changes the program.

9. The Failures That Are Not Races

Two of this module's measured failures have nothing to do with interleaving, and they are worth recognising on sight because their symptoms are distinctive.

A joinable std::thread destroyed. Chapter 26.2 §2 measured it: libc++abi: terminating, exit code 134, and the line after the destructor never printed. This is deterministic, happens on the first run, and the message names no thread and no reason. If a program dies with 134 and a one-line libc++ message, look for a std::thread going out of scope on a path where join was skipped — commonly an early return or an exception, which is Chapter 26.4 §2's shape again and the argument for std::jthread.

A plain bool used as a flag. Chapter 26.7 §4: the waiting thread reported success 1.5 ms in for a flag written at 100 ms, because the loop reading it compiled to a single ret. The symptom is not a hang and not a stale value — it is a wait that does not wait. A loop that returns implausibly fast is worth checking the assembly for.

Both share a property worth generalising: they are deterministic, so they are the easy ones. If a concurrency bug reproduces every time, that is good news — it means you are not looking at a schedule-dependent failure, and Module 25's method applies unchanged.

10. A Method, In Order

1. Is it deterministic? If it fails every run, Chapter 25.5's method works; §9 is where the common ones are catalogued.
2. Is it stopped or spinning? top splits deadlock-and-lost-wake-up from livelock-and-spin in one second, per §7.
3. Run TSan on the whole suite. It finds races without the race having gone wrong, names the line, and exits 134. Budget roughly an order of magnitude of time — 16.4× to 36.5× here depending on synchronisation density.
4. Get a rate, not an anecdote. 100 trials per configuration, fresh state per trial, repeated; report a median and a range, per §3.
5. Amplify deliberately. A barrier, a sleep inside the window, more threads than cores, a different -O level. Then keep the amplified version as the regression test.
6. Attach lldb and read every stack if it is hung. Look for two threads in a lock, or one alone in a wait.
7. Instrument in memory, per thread, and merge after join — never a print per iteration, which §2 measured as closing the window.
8. Make the invariant checkable so the next instance reports itself: private data behind its mutex, a levelled mutex, an owner-thread assert, -Wthread-safety.
9. Reason in happens-before when none of the above settles it. Chapter 26.8 §5 is the only guarantee the language actually gives.

11. The Table

12. What to Actually Do

• Establish first whether it is deterministic. If it is, you have an ordinary bug and Chapter 25.5's method applies.
• Check CPU usage before anything else: zero means blocked, pinned means spinning.
• Run TSan over the whole suite and long realistic runs, gate on exit 134, and read the status directly rather than through a pipe.
• Budget an order of magnitude or more for it and measure the factor on your own code — it was 16.4× on one workload here and 36.5× on another.
• Never measure a sanitizer's overhead against a baseline whose work the optimiser deleted.
• Never draw a conclusion from a run with a print added. Measure the rate with and without, over many trials.
• Report rates with a median and a range, from many trials with fresh state each time.
• Amplify on purpose — a barrier, a sleep in the window, more threads than cores, a different -O — and commit the amplified test.
• Attach lldb and dump every thread's stack for a hang; look for two threads in a lock or one alone in a wait.
• Log per thread into memory and merge after join, with a timestamp and a thread id on every entry. Count rather than narrate.
• Make invariants self-checking: private data behind its mutex, a levelled mutex, an owner assert, a once-flag exchange, and -Wthread-safety where you can.
• Include a control arm in every experiment whose result you can predict, and audit the harness first when a result contradicts something well established.

13. Mistakes Worth Making Once

Adding a print and concluding the bug is fixed. 45.6% lost became 0.5%.

Concluding from three runs that instrumentation always closes the window. The atomic arm ranged 71,044–199,076.

Reporting "it fails about 40% of the time" from one run. The nine runs gave 5 to 54.

Shipping because the un-amplified test passed. 0 of 100, with provably broken code.

Trusting a green concurrency suite. It is evidence about a window, not a program.

Expecting TSan to find a deadlock. It reported nothing here, with the flag set.

Running TSan only on a smoke test. A clean run is not proof; it belongs on the whole suite.

Quoting 111× as TSan's overhead. The baseline had been optimised into nothing.

Combining -fsanitize=thread with -fsanitize=address. They do not co-exist.

Reading interleaved log lines as a timeline. Without a thread id and a timestamp it is fiction.

A log line per iteration in the hot path. You have added a synchronisation primitive.

Assuming exit 134 means a race. It is also the signature of a destroyed joinable thread.

Believing your own harness over the standard library. Chapter 26.5's callout.

14. Interview Relevance

The frozen curriculum marks this High and Expert, and it is the question that separates people who have shipped threaded code from people who have read about it: how do you debug a race that does not reproduce?

Lead with the observer effect, because it is the fact that reframes the question. Adding one fprintf per iteration to a racy loop took it from losing 45.6% of its updates to losing 0.5%. So the first instinct — add a print and watch — removes the symptom, and anyone who has done this recognises the description immediately.

Then give the method rather than a tool list. Establish whether it is deterministic; check whether the process is blocked or spinning; run TSan over the whole suite, because it reasons about whether two accesses were ordered rather than whether this run went wrong, which is why it reported a race in a program that produced the correct answer 800,000 of 800,000; then get a rate from a hundred trials rather than an anecdote, and amplify deliberately with a barrier or a sleep in the window — which moved a deadlock from 0 of 100 to 100 of 100 — and commit the amplified test.

Then the limits, because volunteering them is what makes the rest credible. TSan costs roughly an order of magnitude or more — 16.4× on one workload here, 36.5× on a lock-dense one — so it is a nightly job rather than a per-commit one; a clean run is not proof; it did not detect a real deadlock on this machine even with detect_deadlocks=1; and it cannot run with ASan. Which is why the durable answer is to make the invariant check itself: private data behind its mutex, a levelled mutex that throws on the thread that breaks the order, and clang's -Wthread-safety, which is the only check here that needs no run at all.

15. What You Should Be Able to Say Now

• That a concurrency bug is a function of the schedule as well as the input, so "reproduce it" is not available as step one.
• That observing changes it: an fprintf per iteration took a race from losing 45.6% of its updates to 0.5%, with the range tightening to 196,908–199,916.
• That the atomic-instrumentation arm was unstable (median 104,928, range 71,044–199,076) rather than harmless — and that three runs would have told you either story.
• That the artefact to produce is a rate with a range, from many trials with fresh state: 0 of 100, 39 of 100 [5–54], 100 of 100 for the same defect.
• That amplification is deliberate — a barrier, a sleep in the window, more threads than cores, a different -O level — and the amplified configuration is what belongs in the suite.
• That TSan reasons about the program, not the run: it reported a race in a program that printed 800000 of 800000, named tsanrace.cpp:5 in bump(int), and exited 134.
• That it costs 36.5× [31.0–39.3] on lock-dense code and 16.4× on a mixed workload, gives no false positive on correct code, and that measuring its overhead against an optimised-away baseline produced a junk 111×.
• That it did not find a real deadlock here even with detect_deadlocks=1, that a clean run is not proof, and that it cannot be combined with ASan.
• That when the tools cannot help you, you make the invariant check itself — and that -Wthread-safety is the only check available here that needs no run.
• That a hang triages in one second: CPU at zero means blocked; CPU pinned means spinning — and that lldb is present while valgrind is absent and sample reports an empty call graph.
• That logging must be per thread, in memory, merged after join, with a timestamp and a thread id, and that counting beats narrating.
• That exit 134 with a one-line libc++ message is also the signature of a destroyed joinable thread, not only of a sanitizer finding.

16. Exercises

Exercise 1 — the observer effect. Reproduce §2's three arms over at least twenty-one repetitions. Confirm the fprintf arm's range is tight and the atomic arm's is not.

Exercise 2 — three runs lie. From your §2 data, pick three consecutive atomic-arm results that support "instrumentation always closes the window" and three that refute it.

Exercise 3 — a rate, not an anecdote. Take any racy program and produce §3's table: 100 trials per configuration, fresh state per trial, nine runs, median and range.

Exercise 4 — amplify. Add a barrier before the window, then a 1 ms sleep inside it, and record the rate after each. Then write the regression test you would actually commit.

Exercise 5 — the tool beats the test. Build a race that produces the correct answer at -O2, confirm it over ten runs, then run it under TSan and read both stacks in the report.

Exercise 6 — measure the overhead properly. Measure TSan's slowdown on the racy program and on a mutex-protected one. Explain why the first number is not usable.

Exercise 7 — the hang. Deadlock a program, confirm its CPU is at zero, attach lldb, and find the cycle from thread backtrace all.

Exercise 8 — self-checking. Add guarded_by annotations and -Wthread-safety to a class with a mutex, then write an unguarded access and confirm it fails to compile.

17. Summary

• A concurrency bug lives in the schedule, which is not an input you control, not recorded, and not reproducible on request. Module 25's "reproduce it first" is therefore unavailable, and this chapter's techniques are chosen to not need it.
• Observing changes the bug, measured: an fprintf per iteration took a racy loop from losing 45.6% of its updates (median 108,815 of 200,000) to losing 0.5% (median 198,973, range 196,908–199,916). The diagnostic removes the symptom.
• And instrumentation is not uniformly safe either way: an atomic increment per iteration had a median near the un-instrumented rate but a range of 71,044–199,076, so it is unstable rather than harmless.
• Produce a rate, with a range. The same deadlock fired 0 of 100, 39 of 100 [5–54], and 100 of 100 trials in three configurations differing only in timing — and commit the amplified configuration as the test.
• TSan reasons about the program rather than the run, which is why it reported a race in a program that printed 800000 of 800000 and named tsanrace.cpp:5 in bump(int), exiting 134.
• It costs 36.5× [31.0–39.3] on lock-per-iteration code and 16.4× on a mixed workload, with no false positive on correct code — and measuring it against a baseline the optimiser had deleted gave a meaningless 111×.
• It does not find everything. It reported nothing for a real deadlock on this machine with detect_deadlocks=1, a clean run is not proof, and it cannot run alongside ASan.
• So make the invariant check itself: private data behind its mutex, a levelled mutex that throws on the offending thread, an owner-thread assert, and clang's -Wthread-safety, the only check here that needs no run at all.
• Triage a hang by CPU usage — zero is blocked, pinned is spinning — then attach lldb, which is present here, and read every thread's stack.
• Log per thread into memory and merge after join, timestamped and identified; count rather than narrate.
• And treat a single run as a sample, never an observation. Repeat, publish the spread, include a control arm whose answer you can predict, check the mechanism independently of the behaviour, and audit your harness first when a result contradicts something well established.

That closes Module 26. The module's through-line, if it has one, is that every primitive here is easy and every claim about a concurrent program is hard: a mutex is four and a half nanoseconds and a lock order is a design problem, an atomic is two nanoseconds and a plain bool is a deleted loop, and a passing test is a statement about a window rather than about a program.