Debugging and Observability

Concurrency bugs hide: they vanish when you add a print statement, appear once a week in production, and their symptoms (a hang, a wrong total) are far from their cause.

Learning Objectives

Reproduce intermittent bugs; log in concurrent programs with correlation IDs, thread names and task IDs.

Take thread dumps, detect deadlocks, profile CPU, allocations and lock contention, monitor event-loop lag, inspect pending tasks, read async stack traces, use distributed tracing and histograms.

Use race detectors, thread/address/UB sanitizers, static analysis, stress and randomised testing, deterministic schedulers and virtual time; diagnose flaky tests; find heap, task, goroutine and thread leaks; profile lock-free code; use production-safe diagnostics; write incident analyses and postmortems.

Plain-Language Explanation

Concurrency bugs hide: they vanish when you add a print statement, appear once a week in production, and their symptoms (a hang, a wrong total) are far from their cause. Debugging them means capturing evidence when they happen — stack dumps, logs tagged with who did what, metrics over time — and using tools that find bugs without needing to be lucky, such as race detectors and controlled schedulers.

Precise Technical Explanation

Reproducing intermittent bugs Increase the odds: loops of thousands of runs, more threads than cores, artificial delays at suspected points, stress tools (stress-ng), CPU throttling, different machines/architectures; record seeds and inputs.

Logging in concurrent programs Log atomically per line (most frameworks do), include timestamps with sufficient precision, thread/task names and correlation IDs; avoid logging under hot locks; prefer structured logs.

Log interleaving and correlation IDs Lines from concurrent requests interleave; correlation IDs (Module 20) let you filter one request's story.

Thread names and task IDs Name threads and tasks (threading.Thread(name=…), Thread.ofVirtual().name(…), CoroutineName, pthread_setname_np) so dumps and logs are readable (demonstrated below).

Snapshot every thread's stack: jstack/jcmd Thread.print, dotnet-stack, py-spy dump, faulthandler, gdb thread apply all bt, Go SIGQUIT/pprof goroutine profile.

JVM reports monitor deadlocks automatically in dumps; elsewhere, dump all stacks while hung and build the wait-for graph (Module 5). faulthandler.dump_traceback_later(timeout) gives Python programs an automatic dump when they hang (demonstrated below).

Sampling profilers: perf, async-profiler (JVM), py-spy, dotnet-trace, Go pprof, Chrome DevTools, Instruments.

Heap profilers and allocation flame graphs (JFR, tracemalloc, dotnet-gcdump, Go heap profile).

Lock contention profiling JFR monitor/park events, perf lock, Go mutex/block profiles (runtime.SetMutexProfileFraction),.NET ContentionEvents.

Event-loop lag monitoring Measure how late timers fire: Node perf_hooks.monitorEventLoopDelay() (demonstrated below), asyncio debug mode, custom heartbeats.

Pending task inspection asyncio.all_tasks() + Task.print_stack()/get_stack() (demonstrated below), Kotlin DebugProbes,.NET Parallel Tasks window, Tokio console.

Async stack traces Engines stitch the logical async call chain (V8's zero-cost async stack traces, shown below;.NET; Python task tracebacks).

Spans across services with propagated context (OpenTelemetry, Jaeger, Zipkin) — the cross-process equivalent of a stack trace.

Metrics and histograms Counters, gauges (queue length, active threads, pool usage) and latency histograms; alert on saturation and tail latency.

TSan (C/C++/Go/Rust nightly), Go -race, Helgrind/DRD — dynamic; they find races that occur in the observed execution (Module 3).

ThreadSanitizer specifically: happens-before tracking with shadow memory; 5–15× slowdown, more memory.

Address and undefined-behavior sanitizers where applicable ASan (use-after-free from lifetime bugs across threads), UBSan; cannot be combined with TSan in one build.

Clang thread-safety annotations, Java's Error Prone/SpotBugs (inconsistent synchronization), Infer's RacerD, go vet (copied locks), Rust's compiler, linters for unawaited coroutines/promises (no-floating-promises).

Many threads, iterations and operation mixes with invariant checks (Module 8, 19).

Randomized scheduling/testing Insert random yields/delays (Shuttle, Lincheck's stress mode, CHESS-style tools); PCT (probabilistic concurrency testing) gives guarantees for bugs of small depth.

Deterministic schedulers and virtual time Run tasks under a controlled scheduler where every interleaving and timer is reproducible (Loom, FoundationDB's simulation, Kotlin runTest virtual time, a custom asyncio loop — Module 24).

Timeouts in tests Every concurrent test needs a timeout so deadlocks fail fast with a dump instead of hanging CI.

Flaky test diagnosis Re-run failing tests many times, capture dumps on failure, look for timing assumptions (sleeps), shared state between tests, ordering assumptions, unbounded waits.

Heap and task leak detection Track live object/task counts over time; heap snapshots diff (Module 15 of the Memory course); task counts.

Goroutine/thread/task leak detection runtime.NumGoroutine() and goroutine profiles (demonstrated below), goleak in tests, thread counts in JFR/dotnet-counters, asyncio.all_tasks() at shutdown.

Profiling lock-free code Contention appears as CAS retries and cache misses rather than blocked time — use hardware counters (cache-line contention via perf c2c), retry counters instrumented in debug builds.

Low-overhead, always-on tools: JFR, eBPF/bpftrace, sampling profilers at low frequency, on-demand dumps via signals/admin endpoints, continuous profiling services.

Incident analysis and postmortems Timeline, impact, root cause (often a combination: overload + retry storm + missing timeout), contributing factors, what detection missed, action items; blameless and shared.

Why It Matters in Real Systems

The cost of a concurrency bug is dominated by the time to diagnose it. Teams that name threads, tag logs, export pool and loop metrics, and can take dumps on demand turn week-long hunts into hour-long fixes.

Key Terms

Snapshot of all threads' stacks How late scheduled callbacks run Async stack trace Logical call chain across awaits

Tool reporting unsynchronised conflicting accesses Controlled, reproducible interleaving

Test whose result varies without code changes Structured incident analysis

Syntax and API Overview

This is a concurrency concept, not a language construct; see the tool list above.

Complete Code Example

An automatic Python thread dump when a deadlock hangs the program (CPython 3.13.1 faulthandler.dump_traceback_later; the program exits after dumping):

Pending asyncio tasks and where they are suspended, and thread-named logging (CPython 3.13.1):

Event-loop delay histogram and async stack traces (Node.js 24):

Goroutine profiles reveal leaks by stack (Go 1.23.4):

import faulthandler
import sys
import threading
import time

a, b = threading.Lock(), threading.Lock()

def worker(first, second, name):
    with first:
        time.sleep(0.1)
        with second:                                 # lock-order inversion
            pass

t1 = threading.Thread(target=worker, args=(a, b, "transfer"), name="transfer", daemon=True)
t2 = threading.Thread(target=worker, args=(b, a, "report"), name="report", daemon=True)
faulthandler.dump_traceback_later(1.0, exit=True, file=sys.stdout)   # watchdog: dump all threads after 1 s, then exit
t1.start(); t2.start()
t1.join(); t2.join()

Timeout (0:00:01)!
Thread 0x000027f0 (most recent call first):
  File "m23_py_deadlock_dump.py", line 11 in worker
  File "D:\EngineerHub-tools\python313-pkg\tools\Lib\threading.py", line 992 in run
  File "D:\EngineerHub-tools\python313-pkg\tools\Lib\threading.py", line 1041 in _bootstrap_inner
  File "D:\EngineerHub-tools\python313-pkg\tools\Lib\threading.py", line 1012 in _bootstrap

Thread 0x000042fc (most recent call first):
  File "m23_py_deadlock_dump.py", line 11 in worker
  File "D:\EngineerHub-tools\python313-pkg\tools\Lib\threading.py", line 992 in run
  File "D:\EngineerHub-tools\python313-pkg\tools\Lib\threading.py", line 1041 in _bootstrap_inner
  File "D:\EngineerHub-tools\python313-pkg\tools\Lib\threading.py", line 1012 in _bootstrap

Thread 0x00000534 (most recent call first):
  File "D:\EngineerHub-tools\python313-pkg\tools\Lib\threading.py", line 1092 in join
  File "m23_py_deadlock_dump.py", line 18 in <module>
[exit status 1]

import asyncio
import logging
import threading

logging.basicConfig(format="%(threadName)-10s %(message)s", level=logging.INFO, stream=__import__("sys").stdout)

def background(n):
    logging.info("processing batch %d", n)

threads = [threading.Thread(target=background, args=(i,), name=f"batch-{i}") for i in range(2)]
for t in threads: t.start()
for t in threads: t.join()

async def waits_for_db():
    await asyncio.Event().wait()                        # suspended forever (a leak candidate)

async def main():
    leaked = [asyncio.create_task(waits_for_db(), name=f"db-call-{i}") for i in range(2)]
    await asyncio.sleep(0.01)
    pending = [t for t in asyncio.all_tasks() if t is not asyncio.current_task()]
    print("pending tasks:", sorted(t.get_name() for t in pending))
    frame = pending[0].get_stack()[0]
    print("suspended in:", frame.f_code.co_name, "line", frame.f_lineno)
    for t in leaked:
        t.cancel()
    await asyncio.gather(*leaked, return_exceptions=True)

asyncio.run(main())

batch-0    processing batch 0
batch-1    processing batch 1
pending tasks: ['db-call-0', 'db-call-1']
suspended in: waits_for_db line 15

const { monitorEventLoopDelay } = require("node:perf_hooks");

const h = monitorEventLoopDelay({ resolution: 10 });
h.enable();
setTimeout(() => {
  const end = Date.now() + 150;
  while (Date.now() < end) {}                       // a blocking callback
}, 50);

async function db() { await null; throw new Error("connection reset"); }
async function repository() { return await db(); }
async function handler() { return await repository(); }

setTimeout(async () => {
  h.disable();
  console.log(`event-loop delay: p50 ${(h.percentile(50) / 1e6).toFixed(0)} ms, max ${Math.round(h.max / 1e6 / 50) * 50} ms (the 150 ms blocking callback)`);
  try { await handler(); } catch (e) {
    console.log("async stack trace:");
    console.log(e.stack.split("\n").filter((l) => !l.includes("processTicksAndRejections")).slice(0, 4)
      .map((l) => "  " + l.trim().replace(/\(.*[\\/]/, "(")).join("\n"));
  }
}, 400);

event-loop delay: p50 16 ms, max 150 ms (the 150 ms blocking callback)
async stack trace:
  Error: connection reset
  at db (m23_js_observe.js:10:41)
  at async repository (m23_js_observe.js:11:38)
  at async handler (m23_js_observe.js:12:35)

package main

import (
	"bytes"
	"fmt"
	"runtime"
	"runtime/pprof"
	"strings"
	"time"
)

func leakyWorker(ch chan int) { <-ch } // waits forever: nobody sends

func main() {
	for i := 0; i < 50; i++ {
		go leakyWorker(make(chan int))
	}
	time.Sleep(20 * time.Millisecond)
	var buf bytes.Buffer
	pprof.Lookup("goroutine").WriteTo(&buf, 1) // debug=1: grouped by identical stacks
	for _, line := range strings.Split(buf.String(), "\n") {
		switch {
		case strings.HasPrefix(line, "goroutine profile:"):
			fmt.Println(line)
		case strings.HasPrefix(line, "50 @"):
			fmt.Println("50 goroutines share this stack:")
		case strings.Contains(line, "main.leakyWorker"):
			f := strings.Fields(line) // "#", pc, function+offset, file:line
			fmt.Println("   ", f[2], "at", f[len(f)-1][strings.LastIndex(f[len(f)-1], "/")+1:])
		}
	}
	fmt.Println("runtime.NumGoroutine():", runtime.NumGoroutine())
}

goroutine profile: total 51
50 goroutines share this stack:
    main.leakyWorker+0x24 at main.go:12
runtime.NumGoroutine(): 51

Line-by-Line Explanation

faulthandler.dump_traceback_later(1.0, exit=True) arms a watchdog thread: if the program is still running after 1 s, it prints every thread's stack (both workers inside their second with) and exits — a self-diagnosing hang.

asyncio.all_tasks() lists live tasks; get_stack() shows where each is suspended; cancelling them prevents a leak.

%(threadName)s in the log format labels each line with its thread.

monitorEventLoopDelay samples loop delay; the blocking callback appears as a ~150 ms maximum.

V8's async stack traces include repository and handler although the error was thrown after an await.

The Go goroutine profile groups the 50 leaked goroutines under one stack ending in main.leakyWorker.

Output

Shown above; addresses and some timings vary.

Interleaving or State Trace

Deadlock dump: t = 0 both threads take their first lock; t = 0.1 s both block on their second; t = 1 s watchdog fires, dumps both stacks (each at the with second: line) and exits with status 1.

Correctness and Safety Analysis

Diagnostics must not change behavior much (observer effect): prefer sampling, out-of-band dumps and low-overhead tracing; heavy logging inside critical sections can hide races by changing timing.

Common Mistakes and Misconceptions

Adding prints to "see" a race (changes timing; bug disappears).

Unnamed threads and pools.

No timeouts in tests.

Treating a passing stress run as proof.

Looking only at the thread that crashed, not the one that caused it.

Failure Modes and Debugging Steps

Hang → dump all stacks, find blocked threads and holders. Slow → CPU vs off-CPU (lock/I/O) profiling, loop lag, pool queues. Wrong result → race detector, invariant checks, deterministic replay. Leak → counts over time and grouped stacks.

Performance and Scalability Implications

Always-on diagnostics should cost < 1–2%: JFR, eBPF and sampling profilers qualify; sanitizers and verbose tracing belong in test environments.

Security Considerations

Dumps and logs may contain secrets and personal data — restrict access; diagnostic endpoints must be authenticated.

Platform and Runtime Caveats

Tool availability differs (no TSan for pure Python; py-spy needs ptrace permissions; Go pprof built in; JFR built into the JDK since 11; .NET diagnostics tools are separate global tools).

Real-World Applications

On-call debugging with thread dumps, continuous profiling (Pyroscope, Datadog), JFR in production JVMs, Node loop-lag dashboards, Go pprof endpoints, blameless postmortems.

Best Practices

Name every thread, pool and task; tag logs with correlation IDs.

Export pool, queue and loop-lag metrics; alert on saturation.

Arm watchdogs that dump stacks on hangs; put timeouts in tests.

Run race detectors/sanitizers in CI; use deterministic schedulers for complex protocols.

Write postmortems with concrete follow-ups.

Exercises

E1 · Beginner. Why might adding a print make a race condition disappear?

Answer: Printing takes time and often takes a lock (stdout), changing the interleaving so the racy window is rarely hit — the bug is hidden, not fixed.

E2 · Intermediate. A Node service's p99 doubled after a release; CPU is low. What do you check?

Answer: Event-loop delay (a new synchronous operation blocking the loop), pool waits (database or HTTP agent saturation), downstream latency via traces, and GC pauses — CPU being low points to waiting, not computing.

E3 · Advanced challenge. Design a CI strategy for a flaky concurrent test.

Answer: Quarantine it from the main signal; run it N times in a loop with randomised seeds and stress; capture thread dumps/sanitizer reports on failure; add timeouts; replace sleeps with latches; reproduce under a deterministic scheduler; fix the root cause before re-enabling.

Quiz

? What does faulthandler.dump_traceback_later(t, exit=True) do?
+ Dumps all threads' stacks if the program is still running after t seconds, then exits. :: A hang watchdog.
- Prevents deadlocks. :: It reports them.
- Profiles CPU usage. :: It dumps stacks.
- Restarts hung threads. :: Threads cannot be restarted.

? A Go goroutine profile shows 10,000 goroutines with the same stack blocked on a channel receive. What is it most likely?
+ A goroutine leak :: Many identical blocked goroutines.
- Normal idle worker pool :: A pool would have a bounded, small count.
- A data race :: That needs the race detector.
- GC pressure :: Unrelated to blocked goroutines.

? Which are suitable for always-on production diagnostics? (select all that apply)
+ Java Flight Recorder :: Low overhead.
+ Sampling profilers at low frequency :: Low overhead.
- ThreadSanitizer builds :: 5-15x slowdown.
+ Event-loop delay histograms :: Cheap metrics.

Summary

Debug concurrency with evidence: named threads and tasks, correlated logs, thread dumps and watchdogs, profilers for CPU, allocations, locks and loop lag, async stack traces, distributed tracing, race detectors and sanitizers, stress and controlled scheduling, leak counts — and learn from incidents with postmortems.