Decomposing End-to-End Latency into Waiting and Serving

A single elapsed-time figure for a request is almost useless for improvement, because it does not say which of the many things that could have taken time actually did. The productive measurement splits the total into intervals with distinct causes: time waiting for a slot to run, time running, time waiting for a response from something else, and time spent moving bytes. The split is what converts a latency complaint into a change.

Doing the split correctly is harder than adding up stage timers, because the stages overlap, because some of them are invisible from inside the process, and because the intervals that matter most are the ones where nothing is executing.

The four intervals a request occupies

Every request traverses a sequence of intervals that partition its elapsed time if the boundaries are drawn consistently:

• Queueing. The request exists and is eligible but has not started executing, because a worker, connection, lock, or scheduler slot was not available.
• Serving. A thread or process is executing on the request’s behalf.
• Blocked on a dependency. The request has handed work to another component and is waiting for the answer, so no local execution is occurring.
• Transfer. Bytes are moving over a link, which for a large payload or a slow link is a duration independent of both queueing and serving.

The partition is exhaustive only if every nanosecond of the elapsed time lands in exactly one of these. That is the discipline the split imposes, and it immediately exposes the largest single error in most latency investigations: the assumption that elapsed time is mostly serving time. In systems that queue, the opposite is common, and the serving interval is a minority of the total.

Why summing stage timers overcounts

The natural instrumentation adds a timer around each stage and reports the sum. The sum exceeds the true elapsed time for three reasons, each of which produces a different signature.

Nested stages are counted twice. If a handler timer wraps a database call timer, the database interval is counted once as part of the handler and once on its own. A trace that shows 40 milliseconds in the handler and 30 in the database does not imply 70 milliseconds of work unless the database call is outside the handler interval, and the instrumentation rarely states which.

Parallel stages are added when they should be maxed. A request that fans out to three services concurrently and waits for all three takes the duration of the slowest, not the sum. Adding the three stage timers produces a number that can be three times the real elapsed time, and the error grows with fan-out width.

Retries are additive but the original attempt’s queueing is shared. A request that fails, waits a backoff, and retries has two serving intervals and one queueing interval before the first attempt, but the backoff sleep belongs to none of the four categories unless it is counted as blocked. Instrumentation that times only the successful attempt understates the total by everything before it.

The reliable check is a closure test: the sum of the top-level, non-overlapping intervals must equal the measured elapsed time to within the clock resolution and the instrumentation’s own overhead. When it does not, the discrepancy is itself a finding, and the usual cause is an interval nobody instrumented.

The uninstrumented intervals

Three intervals account for most closure failures, and none of them appear in application-level timers.

Time in the kernel’s accept queue. A connection that has completed the TCP handshake but has not been accepted by the application sits in a queue whose depth is bounded by the listen backlog. From the client’s perspective the request has started; from the server process’s perspective it does not exist. The interval is measurable from the difference between the client’s first byte and the server’s accept timestamp, and it can be arbitrarily large when the application is not calling accept quickly enough.

Time in the run queue. A thread that is runnable but not scheduled is queueing, and the queue is the CPU. Off-CPU time of this kind is invisible to wall-clock timers inside the thread, since the thread is not executing to read its own clock, but it is visible as the difference between the time a request was made runnable and the time it first ran. Scheduler delay of this kind grows with the number of runnable threads per core, and it is a queueing delay in the precise sense of the utilization curve.

Time between the request being written and the response being read. On a network path this includes propagation delay, which for a path crossing an ocean is tens of milliseconds and is not reducible by any change to the code. It is bounded below by the speed of light in fibre, roughly 200 kilometres per millisecond, so a 10,000-kilometre round trip cannot be faster than about 100 milliseconds regardless of how fast the endpoints are.

A decomposition that omits these three produces a picture in which the application looks responsible for latency that it never caused, and improvement effort goes into optimizing code that is not on the critical path.

Measuring the split with paired timestamps

The measurement requires a timestamp at each boundary, taken from a clock with a known relationship to the others. On a single host, a monotonic clock suffices. Across hosts, the clocks differ, and the difference is a systematic offset that appears as negative durations when a child span is reported as starting before its parent.

import time

class Span:
    def __init__(self, name):
        self.name = name
        self.t0 = time.monotonic_ns()
        self.children = []
        self.self_ns = 0        # exclusive time, computed after children close

    def __enter__(self):
        return self

    def __exit__(self, *exc):
        self.t1 = time.monotonic_ns()
        # exclusive time excludes children, so nested spans do not double-count
        covered = sum(c.t1 - c.t0 for c in self.children)
        self.self_ns = (self.t1 - self.t0) - covered

    def child(self, name):
        s = Span(name)
        self.children.append(s)
        return s

The exclusive-time computation is the mechanism that makes the closure test possible: each span reports only the time during which it, and not a descendant, was active. Summing exclusive times across a trace yields the elapsed time of the root, provided no time is unattributed. Unattributed time is the gap between the root’s total and the sum of its children’s totals, and it is exactly the queueing and blocked time that the instrumentation did not capture.

The clock problem across hosts

Two hosts’ clocks differ by an unknown amount, and the difference drifts. Subtracting one host’s timestamp from another’s therefore produces a duration with an error equal to the offset, which can be milliseconds or worse on unsynchronised clocks and microseconds when synchronised by a network time protocol.

The consequence is that cross-host spans cannot be used to attribute sub-millisecond intervals, and that a negative duration between a parent and a child is a clock artifact rather than evidence of causality violation. Implementations handle this by recording the offset estimate alongside the timestamps, or by ordering events within a host and using only within-host differences for the decomposition, with cross-host intervals reported as elapsed times whose internal split is unknown.

This is the reason a decomposition is most trustworthy within one process and degrades as it crosses boundaries. The degradation is not a reason to skip the cross-host part; it is a reason to state which intervals are measured and which are inferred.

What the split buys

Once the intervals are separated, the improvement strategy follows from which one dominates, and the strategies are not interchangeable.

If queueing dominates, the fix is capacity or admission control. Adding workers reduces the queue length per worker, but only if the queue is per-worker; a shared queue with more workers reduces waiting until the workers themselves contend for a shared resource, at which point the bottleneck has moved. The relevant measurement is the distribution of queue depth, not just the mean, because the mean queue depth of 1.5 is compatible with a system that is empty 60 percent of the time and has 5 requests queued 15 percent of the time.

If serving dominates, the fix is to reduce work, which is the domain of profiling rather than queueing. The distinction matters because a serving-time problem does not respond to added capacity in the way a queueing problem does: doubling the servers halves the queueing delay but leaves the per-request serving time unchanged, so a service that is 90 percent serving time gains almost nothing from horizontal scaling.

If blocked-on-dependency dominates, the fix is at the dependency or in the interaction pattern. Caching removes the call; batching amortizes it; parallelizing hides it; and reducing the number of round trips per request removes multiplicative latency. This is the interval where the fan-out arithmetic of the tail-at-scale problem applies most directly, since each dependency call is an opportunity for the request to wait on the slowest of many.

If transfer dominates, the fix is at the payload or the path: compression, a smaller representation, a closer endpoint, or a protocol that avoids per-round-trip overhead. This interval is the one where no amount of server-side optimization helps, and it is identifiable only because the decomposition separates it.

The split also determines whether the system is operating in the region where the utilization curve is steep. A request that is 80 percent queueing is on the steep part by definition, since the queueing share rises with utilization while the serving share does not. The relationship between the two shares and the load level is treated in Utilization and the Nonlinear Growth of Waiting Time.

Limits of the decomposition

The method assumes a request has an identifiable start and end. Streaming responses, long-poll connections, and websockets do not, and the decomposition has to be applied per message rather than per connection, which changes what the intervals mean.

It also assumes that time is spent doing one thing. A request that is simultaneously blocked on two dependencies, for example a connection pool wait while a timeout ticks, occupies both intervals at once, and the partition breaks. In that case the intervals are not a partition but a covering, and the sum exceeds the total for a legitimate reason rather than an instrumentation error.

Finally, the decomposition describes where time went in the sample that was traced. Traces are usually sampled, and the sampling is usually biased toward interesting requests, so the traced population’s split is not the population’s split. The bias is acceptable when the question is “what does a slow request look like” and unacceptable when the question is “what fraction of total latency is queueing,” which requires either a representative sample or a separate aggregate measurement of queue depth and service time; the reporting discipline that distinguishes a distribution-shaped claim from a population claim is set out in Means, Percentiles, and What a Tail Measurement Can Answer.