Debugging Concurrency

What to Instrument in a Concurrent System

Request rate, error rate and duration describe the work. They say nothing about whether forty threads are asleep in front of one lock. Concurrency observability adds a second axis — where the work is *waiting* — and there are exactly six signals worth the cardinality.

The question this answers

The question

Which signals tell me my system is concurrency-limited rather than slow?

The work

A request-handling service with a 32-thread pool, a job queue and one shared in-memory index guarded by a lock.

What is shared

The pool itself (a fixed number of threads), the queue between arrival and execution, and the lock around the index. All three are shared by every request in flight.

The invariant — what must stay true under every interleaving

The number of requests currently executing never exceeds the pool size, and every request either holds a worker or is counted in the queue — nothing is in flight and invisible.

Synchronization exists to preserve this sentence. If a schedule can make it false, the code is wrong no matter which primitive it uses.

WorkCan it overlap?Can it parallelise?What is shared?What ordering?What synchronization?Where is contention?What can deadlock?What can race?What is gained?What complexity?

Six signals, and what each one rules out

The general observability toolkit — Observability Is Not a Dashboard, The Four Golden Signals, RED: Rate, Errors, Duration — tells you the service is slow. It cannot tell you whether the slowness is compute, downstream latency, or thirty threads queued behind a mutex, because all three produce the same duration histogram. The concurrency-specific signals exist to split that.

Six are worth the cost. Thread state counts (how many runnable, how many blocked) separate "busy" from "stuck". Lock wait time separates contention from work. Queue length and queue age separate arrival-rate problems from service-rate problems. Event-loop lag catches a single-threaded runtime that has stopped scheduling. Worker utilization tells you whether the pool is the ceiling. Task duration, split by state, tells you where inside a task the time went.

Everything else on this list is already taught elsewhere and should be linked, not re-derived: the *diagnosis* of lock contention lives in Low CPU, High Latency: Lock Contention, queue arithmetic in Queueing: Why Systems Get Slow Before They Get Broken and Depth Is Not an Emergency; Age Is, pool exhaustion in Twenty Workers, All Busy, Five Hundred Waiting. What is concurrency-specific here is which signal answers which question, and the fact that the aggregate ones lie by construction.

SignalEmit asRules inWrong conclusion it prevents
Threads by state (running / runnable / blocked / waiting)gauge per stateSaturation vs blockage"CPU is at 30%, we have headroom" — when 28 of 32 threads are blocked
Lock wait timehistogram, per lock nameContention on a specific region"The handler got slower" — when the handler is unchanged and the lock is not
Queue length + queue agegauge + histogramArrival rate above service rate"The queue is short so we are fine" — a short queue with old entries is a stalled consumer
Event-loop laghistogram of scheduling delayA blocked single-threaded runtime"The service is up" — the health check is also queued behind the blocked tick
Worker utilization (busy workers / pool size)gaugePool size as the ceiling"Add machines" — when one pool setting is the limit on every machine
Task duration split by running vs waitingtwo histogramsWhere inside the task the time went"p99 is 900ms" — with no idea whether that is work or waiting
Signal → what it rules in, and the wrong conclusion it prevents.

The aggregate that hides the problem

Concurrency signals are unusually hostile to averaging. A pool of 32 workers where 4 are pinned on a slow downstream and 28 idle has the same mean utilization as one where all 32 are half-busy — and only the first is one slow dependency away from total unavailability. The same is true of lock wait: a mean of 3ms is compatible both with every caller waiting 3ms and with 99% waiting nothing while 1% wait 300ms.

So emit distributions, not means, and label by the thing that varies: lock name, queue name, pool name, task type. That is a cardinality decision — see Cardinality: The Label That Took Down Monitoring and Label Sets That Survive a Year — and the honest version is that lock name is safe (there are a dozen), while lock name × request path is not (there are thousands).

The read-out below is what a healthy service and a contended one look like side by side on exactly these six signals. Nothing in the RED view distinguishes them until the very last line.

                              HEALTHY          CONTENDED
threads.running                    11               3
threads.runnable                    2               1
threads.blocked                     1              27      <-- the whole story
threads.waiting (io)               18               1

lock.index.hold_time     p50      0.4ms           0.4ms    <-- unchanged
lock.index.wait_time     p50      0.1ms           41ms
lock.index.wait_time     p99      2.1ms          610ms

queue.jobs.length                   4             112
queue.jobs.oldest_age              80ms           9.4s

pool.workers.busy / size        13 / 32         31 / 32
task.duration.running    p99      120ms          128ms     <-- unchanged
task.duration.waiting    p99       18ms          640ms

http.request.duration    p99      190ms          810ms     <-- the only RED signal that moved
The same service, two minutes apart. Illustrative shape, not a measurement.

Where this instrumentation belongs, and what it costs

Lock wait is measured at acquisition: record the time from "attempt to acquire" to "acquired", not the time the lock is held. Those are different numbers and confusing them is the single most common instrumentation bug in this area — see Hold Time, Wait Time, and the Ratio Between Them, which is entirely about their ratio. Queue age is measured at dequeue, from the enqueue timestamp carried on the item; queue length is sampled. Event-loop lag is measured by scheduling a zero-delay callback and recording how late it actually ran.

Every one of these adds a timestamp read on a hot path. On a lock acquired a million times a second, two clock reads per acquisition is a real cost and is itself a source of contention if the counter is a shared cache line — see False Sharing: Different Variables, Same Cache Line. The practical answer is sampling, or per-thread counters aggregated on scrape, and the general treatment is Instrumentation: From Code to Signal and Always-On Profiling, and the Diff That Finds Regressions.

Finally: instrument the *invariant*, not just the timings. A counter of "tasks started minus tasks finished" that drifts upward is the cheapest orphaned-task detector that exists, and it costs two atomic increments — see Orphaned Tasks.

Where each measurement is taken along one request
enqueue ts stampedage = now - enqueue tswait ends, hold beginsArrivalQueue (length, age)Worker assigned (utilization)Lock acquire (WAIT time)Critical section (HOLD time)Downstream I/O (waiting duration)Response (RED duration)
ClientGateway / LBServiceWorkerDatabaseCacheQueue / LogObject storageCDNExternal system

Key points

  • RED and the golden signals describe the work; they cannot distinguish compute from blocking, which is why concurrency needs its own axis.
  • Six signals carry it: thread state counts, lock wait time, queue length and age, event-loop lag, worker utilization, and task duration split into running versus waiting.
  • Measure wait time at acquisition and hold time inside the critical section — they are different numbers and only their ratio is diagnostic.
  • Means are actively misleading here: 28 blocked and 4 busy averages to the same utilization as 32 half-busy, and only one of those is about to fall over.
  • The cheapest correctness signal in the whole domain is "tasks started minus tasks completed", and almost nobody emits it.

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.

How it works
  • At enqueue, stamp the item with a monotonic timestamp; at dequeue, record now minus that stamp as queue age.
  • Wrap lock acquisition so the interval between the attempt and the grant is recorded as wait, and the interval between grant and release as hold, under the lock's name as a label.
  • Sample thread or task state periodically from the runtime and export one gauge per state, so "blocked" is a first-class number rather than an inference from low CPU.
  • Schedule a zero-delay callback on a repeating interval and export the difference between when it should have run and when it did — that difference is event-loop lag.
  • Split task duration into two histograms at every suspension point: time on-CPU and time waiting, so the p99 can be attributed rather than merely reported.
Interleavings that matter
  • Worker A holds the index lock and issues a downstream HTTP call inside the critical section; workers B..Z arrive, block on acquire, and thread.blocked climbs to 27 while CPU stays at 8% — every dashboard reads "idle" while the service is fully stalled.
  • A scrape samples queue.length between two bursts and reads 4; between scrapes the queue reached 900 and drained. Length alone said healthy; queue age at dequeue would have shown 9-second-old items.
  • The metrics exporter itself acquires the same lock to read the counter it is exporting, so the act of scraping adds a waiter and the contention metric is partly self-inflicted.
What it guarantees — and does not
  • These signals guarantee that blocking is *visible*. They do not tell you which lock ordering caused it, which code path holds the lock, or whether the wait is fair.
  • Thread state counts are a sample, not a trace: they prove threads were blocked at sampling instants and say nothing about the schedule between samples.
  • Event-loop lag proves the loop was late. It does not identify the callback that was long — that needs a profile, see Off-CPU Time: The Thing a CPU Profiler Cannot See.
  • None of these prove correctness. A system can have perfect lock-wait metrics and still lose updates, because a lost update is a schedule, not a duration.
Where contention appears
  • The instrumentation is itself shared state. A global histogram updated under a lock turns every measured acquisition into two acquisitions.
  • High-cardinality labels multiply memory in the metrics client and CPU in the exporter, and both live in the same process as the work.
  • Sampling thread state may require a runtime-level stop or a lock inside the runtime, so a 1Hz sample is fine and a 1kHz sample is a new bottleneck.
How it fails
  • Blind spot: no lock instrumentation at all, so a contention incident is diagnosed as "the database got slower" and a week is spent on the database.
  • Wrong quantity: hold time exported and labelled "lock time", so contention that shows only in wait time is invisible.
  • Aggregation loss: per-pool means that hide a single saturated pool among ten idle ones — the hot-key shape from Hot Keys: When Aggregate Metrics Hide a Saturated Node.
  • Observer cost: instrumentation on a lock acquired millions of times per second becomes a measurable share of the very latency it measures.
  • Missing liveness: no started-minus-completed counter, so orphaned tasks accumulate silently until memory does the reporting.
When it helps
  • Any service with a fixed worker pool, where the difference between "needs more machines" and "needs a smaller critical section" is a five-figure decision.
  • Single-threaded runtimes, where event-loop lag is the only signal that distinguishes a stalled process from a busy one.
  • Post-incident, where the question is always "was it blocked or was it working?" and only these signals answer it.
When it hurts
  • Ultra-hot paths where two clock reads per acquisition are a meaningful fraction of the operation — sample instead of measuring every acquisition.
  • Systems with no shared locks and no pools, where the whole apparatus measures nothing and adds cardinality to the bill.
  • When it becomes a substitute for reasoning: a lock-wait dashboard tells you where threads waited, never which interleaving corrupted the data.
How you would know
  • Blocked thread count above a small fraction of pool size, sustained, with CPU well under capacity — the canonical contention shape.
  • Lock wait p99 rising while lock hold p50 stays flat: more arrivals at an unchanged critical section.
  • Queue age rising while queue length is flat: the consumer is stalled, not overwhelmed.
  • Event-loop lag p99 above a few tens of milliseconds on a runtime that is supposed to be responsive.
  • Task started-minus-completed drifting monotonically upward across a deploy.
Complexity it introduces
  • Every wrapped lock is a new abstraction that must not change acquisition semantics — a wrapper that silently makes a lock reentrant is a correctness change disguised as instrumentation.
  • Six new signal families to name, label, retain and alert on, each with its own cardinality budget.
  • Two histograms per task instead of one duration, which doubles the storage for the most-emitted metric in the service.
  • On-call has to learn a second mental model: the RED dashboard and the concurrency dashboard disagree by design, and the second one is right about causes.
Simpler alternatives
  • A periodic thread dump on a timer, kept for an hour. Far cheaper than continuous instrumentation, and for an intermittent stall it is often sufficient — see Reading a Thread Dump.
  • Continuous profiling with off-CPU support, which subsumes lock-wait metrics at higher fidelity and higher cost — see Off-CPU Time: The Thing a CPU Profiler Cannot See.
  • Nothing at all, if the service has one thread, no locks and no queue. The correct amount of concurrency instrumentation for a system with no concurrency is zero.
  • Distributed tracing with explicit wait spans, when the waiting you care about crosses services rather than threads — Distributed Tracing.

What people believe, and what is true

Claim

If CPU is low we have headroom.

Reality

Low CPU with high blocked-thread count is the signature of a fully saturated system. The resource that ran out was the lock, not the processor.

Claim

Lock time is one metric.

Reality

Hold time and wait time are different measurements taken at different moments, and the diagnosis lives in their ratio, not in either one.

Claim

Tracing already covers this.

Reality

A span shows a handler took 800ms. Unless someone explicitly instrumented the acquire, nothing in the span says 640ms of it was spent queued behind a mutex.

Apply it