The question this answers
Why does adding a print statement make my concurrency bug disappear, and what do I do instead?
A lazily-initialized configuration object read by every request thread, where two threads can both observe it as uninitialized and both construct it.
The config pointer and the object it points to, read by every thread and written by whichever thread wins the initialization.
Every thread that reads config observes a fully-constructed object, and exactly one construction is performed.
Synchronization exists to preserve this sentence. If a schedule can make it false, the code is wrong no matter which primitive it uses.
Why observation changes the schedule
The normal debugging loop is: reproduce, observe, hypothesize, change, confirm. Concurrency breaks it at step two, because in a concurrent program *observation is execution*. A print statement is not a passive read. It formats a string (allocation), takes the output stream's lock (synchronization), and writes to a file descriptor (syscall, and very likely a scheduler yield). Any one of those can be enough to move a thread out of a window measured in nanoseconds.
A breakpoint is far worse. Stopping one thread while the others run does not slow the program down uniformly — it changes the *relative* order of everything, which is precisely the variable the bug depends on. A single-threaded bug is invariant under this; a concurrency bug is defined by it.
The direction of the effect is also asymmetric in an unhelpful way. Most instrumentation *widens* the gap between two operations in the instrumented thread, which usually makes the racing thread more likely to slip in — except when the instrumentation happens to introduce a synchronization edge that accidentally fixes the ordering. Both outcomes look like "adding logging changed the bug", and only one of them is a clue.
| # | Thread A | Thread B | State |
|---|---|---|---|
| 1 | read config (null) | · | config=null constructions=0 |
| 2 | branch taken: needs init | · | config=null constructions=0 |
| 3 | · | read config (null) | config=null constructions=0 |
| 4 | · | branch taken: needs init | config=null constructions=0 |
| 5 | construct object #1, write config | · | config=obj#1 constructions=1 |
| 6 | · | construct object #2, write config | config=obj#2 constructions=2 ✕ Exactly one construction. Two were performed, and threads already holding obj#1 now diverge from later readers holding obj#2. |
| 7 | registers a callback on obj#1 | · | config=obj#2 constructions=2 |
A window measured against a probe
It helps to think numerically. The window in the schedule above — between reading null and writing the pointer — might be a few hundred nanoseconds. A formatted log line to a file is commonly several microseconds. A breakpoint is milliseconds to seconds. Each probe is one to seven orders of magnitude larger than the thing it is trying to observe, which is why the probe dominates the result.
The read-out below is the arithmetic laid out. Notice what stays usable: a pre-allocated ring-buffer trace entry costs tens of nanoseconds and does not synchronize, so it perturbs the window by a fraction rather than by orders of magnitude. That is the general escape route — record cheaply into per-thread storage and analyse afterwards, rather than observing synchronously.
The related trap is a *release/debug* difference. A debug build disables optimizations, changes struct layouts and inlining, and often adds bounds checks, all of which shift timing. "It only happens in release" is not a compiler bug report; it is usually a timing statement, and occasionally a genuine memory-model statement about a reordering the optimizer performed — Reordering: The Compiler and the CPU Both Do It.
THE WINDOW read config (null) -> write config ~ 200 ns PROBES, BY COST per-thread ring-buffer trace entry ~ 20 ns 0.1x window usable atomic counter increment ~ 30 ns 0.15x usable timestamped event into preallocated slot ~ 60 ns 0.3x usable --------------------------------------------------------------------------- formatted log line to stdout (locked) ~ 5,000 ns 25x window moves log line to a synchronous file sink ~20,000 ns 100x window moves conditional breakpoint evaluated in-process ~50,000 ns 250x window gone attaching a debugger and stepping ~10^9 ns 5,000,000x different program RULE OF THUMB if the probe costs more than the window, you are no longer measuring the program you are trying to debug.
The loop that works instead
Since observation perturbs, the working method inverts the order: *reason first, then confirm*. Start from the invariant and enumerate the interleavings that could break it — Reasoning About Races: A Method, Not an Instinct is that skill — and only then look for evidence of the specific schedule you predicted. This is genuinely different from single-threaded debugging, where poking at the running program is efficient.
The three tools that survive perturbation are: cheap post-hoc tracing (write to per-thread buffers, reconstruct afterwards), a race detector (which reports the unordered pair whether or not it manifested — Race Detectors: What They Find, and What They Structurally Cannot), and stress testing with injected delays, which deliberately *widens* windows instead of accidentally narrowing them — Stress Testing: A Test That Passed Once Proves Nothing. Deterministic replay is the fourth and strongest, because it removes the nondeterminism entirely — Deterministic Replay: Making the Schedule Reproducible.
The compare below shows the practical form of the tracing rule: not "remove logging" but "make the probe smaller than the window". Record an event index into a per-thread array with no locks and no formatting; dump and interleave the arrays after the failure. The information is the same; the cost is a hundredth.
1if config == null:2 log.info("thread " + id + " sees config null at " + timestamp())3 # ^ allocates, formats, takes the logger lock, writes to a fd.4 # ~5us of work and one likely yield, inside a ~200ns window.5 # The bug stops reproducing. Nothing was fixed.6 config = buildConfig()1# per-thread, preallocated, no lock, no allocation, no syscall2TRACE_SAW_NULL = 13TRACE_WROTE = 24 5if config == null:6 trace[tid][n[tid]] = (TRACE_SAW_NULL, rdtsc()) # ~20ns7 n[tid] += 18 config = buildConfig()9 trace[tid][n[tid]] = (TRACE_WROTE, rdtsc())10 n[tid] += 111 12# after the failure: merge all per-thread buffers by timestamp and13# read off the actual interleaving. Same information, 1/250th the probe.The information you wanted was "which thread saw null, and when". Formatting a string and taking the logger lock is not required to record that, and it is the formatting and the lock — not the recording — that move the schedule. Shrink the probe below the window and the bug keeps reproducing while you watch it.
Key points
- In a concurrent program, observation is execution: a log line allocates, locks and syscalls, and any of those can close a nanosecond-scale window.
- A breakpoint is the worst probe available, because stopping one thread changes the relative order of all the others — the exact variable the bug depends on.
- The rule of thumb is quantitative: if the probe costs more than the window, you are debugging a different program.
- Instrumentation can also accidentally *fix* the bug by introducing a synchronization edge, which looks identical to "it went away" and is not a clue.
- The method that works inverts the loop: reason from the invariant to a candidate schedule first, then gather evidence for that specific schedule.
- Probes that survive: per-thread lock-free trace buffers, atomic counters, race detectors, and deliberately widened windows in stress tests.
The loop, answered
Every field is required, which is why no lesson here can recommend concurrency without naming the interleaving that breaks it, the complexity it adds, and the simpler thing to consider first.
- • A concurrency bug requires a specific relative ordering of operations from different actors; the set of orderings that trigger it may be a tiny fraction of all orderings.
- • Any probe that adds work, takes a lock, allocates, or performs a syscall changes the duration of one actor's step and therefore the probability distribution over orderings.
- • Adding a lock-taking probe can also create a happens-before edge that did not exist, converting a racy program into an ordered one for as long as the probe is there.
- • Debug builds change inlining, layout and optimization, shifting timing globally rather than at the probe site — hence "only in release".
- • The counter-move is to make the probe cheaper than the window, or to widen the window deliberately so that ordinary probes no longer dominate it.
- • A reads null, B reads null, A constructs and writes obj#1, B constructs and writes obj#2 — two objects, and every reference already handed out to obj#1 is now orphaned.
- • With a log line inserted after A's read: A yields for ~5µs, B completes read-construct-write entirely, A re-checks (in a double-checked variant) and finds non-null, returns B's object. One construction, correct result, bug "not reproducible".
- • With a *breakpoint* after A's read: A is stopped for seconds while B runs to completion thousands of times. Not only does the bug not reproduce, the developer concludes the code is fine.
- • Under a stress harness that injects a 5ms sleep at the same point: the window is now 25,000x its natural size, B lands inside it on essentially every run, and the bug reproduces on demand. Same perturbation principle, used deliberately and in the useful direction.
- • The disappearance of a bug under instrumentation guarantees nothing about the bug. It is evidence about the probe, not about the code.
- • A cheap per-thread trace guarantees the events it recorded and their local order; merging across threads by timestamp is approximate unless the clock source is genuinely comparable across cores.
- • Reproducing under a debugger guarantees the bug is not purely timing-dependent — which is useful negative information and rarely what you are chasing.
- • No amount of "it stopped happening" is evidence of a fix. Only a mechanism plus a test that reliably reproduced the failure before the change and reliably does not after it.
- • The probe itself contends: a shared logger lock serializes every instrumented thread, which is why it changes the schedule so effectively.
- • Per-thread buffers avoid lock contention but can still cause false sharing if adjacent threads' slots land on one cache line — see False Sharing: Different Variables, Same Cache Line.
- • Timestamp sources may serialize on some platforms, turning a "cheap" probe into a synchronization point.
- • Declaring victory: the bug stopped reproducing after a logging change, the ticket is closed, and it returns under production load six weeks later.
- • Debugging the probe: hours spent on why the log line "fixes" it, rather than on which schedule the log line prevented.
- • Shipping the probe as the fix — a
sleep(1)or a stray log line that suppresses a window and becomes load-bearing code nobody dares remove. - • False sharing introduced by the tracing arrays, changing the timing the tracing was supposed to observe.
- • Concluding from "only in release" that the compiler is broken, rather than that the release build's timing or reordering exposes a real bug.
- • Recognizing the pattern early — "it went away when I added logging" should immediately reclassify the bug as timing-dependent and change the whole approach.
- • Justifying investment in a stress harness or replay tooling, because the ordinary loop is demonstrably not going to converge.
- • Reading historical incidents: a bug that only appears on the busiest node or the fastest machine is telling you about window sizes.
- • As an excuse. "It is a heisenbug" is sometimes used to stop investigating, when the invariant and the candidate schedules were never enumerated.
- • When applied to bugs that are not timing-dependent at all — memory corruption and uninitialized reads also move under instrumentation and need entirely different tools.
- • When the team over-rotates to lock-free trace buffers for problems a five-minute reading of the critical section would have solved.
- • Reproduction rate as a number: "1 in 40,000 requests" is a workable starting point; "sometimes" is not.
- • Whether reproduction rate changes with load, core count, machine speed or build type — each of those points at a different window.
- • Whether the bug survives a per-thread cheap trace. If it does, you have an observation channel and can proceed normally.
- • Whether an injected delay at the hypothesized window raises the reproduction rate. A yes is strong confirmation of the hypothesis.
- • A second, cheaper observation channel to build and maintain, with its own dump-and-merge tooling.
- • Reasoning-first debugging is a genuinely harder skill than printf debugging and does not come for free with experience in single-threaded work.
- • Delay injection has to be conditional and removable, or it becomes production behaviour by accident.
- • Cross-thread timestamp comparison is subtle enough that the merged trace can itself be misleading if the clock source is not consistent.
- • Deterministic replay, which removes the nondeterminism so ordinary debugging works again — the strongest answer, and not free. See Deterministic Replay: Making the Schedule Reproducible.
- • A race detector, which reports the unordered access without needing the bug to manifest and without depending on timing — Race Detectors: What They Find, and What They Structurally Cannot.
- • Code reading against a written invariant. For a small critical section this converges faster than any tool.
- • Removing the sharing entirely — a single initialization at startup, or an immutable snapshot — so there is no window to observe. See Immutability as a Concurrency Strategy and Initialization Races.
What people believe, and what is true
The bug went away when I added logging, so the logging fixed it.
The logging changed the schedule. The bug is still there for every schedule the logging did not prevent, which is most of them once the logging is removed.
If I cannot reproduce it under a debugger, it is not a real bug.
A debugger is the largest possible perturbation. Non-reproduction under one is expected for this class and is evidence of nothing.
It only happens in release, so it is a compiler bug.
Almost always it is your bug, exposed by different timing or by a legal reordering the optimizer performed on code that never established the ordering it relied on.