A trace shows the caller's HTTP span at 180 ms and the callee's own span for the same call at 20 ms. In a second trace, a parent span's first child starts 140 ms after the parent begins. What sits inside each gap, and what do you check first?
Show the full answer Hide the answer
The two spans measure different things
A client span opens before the request leaves and closes after the response is parsed. It therefore contains connection acquisition, DNS and the TLS handshake if the connection is cold, serialisation of the body, the network in both directions, the time the request spent in the server's accept and worker queues, and any retry the client library performed internally.
A server span opens when the framework hands the request to a handler, which happens after all of that queueing. So the 160 ms difference is not a discrepancy and nobody is misreporting: it is everything the callee does not count as its own work, and queueing is usually most of it.
What the 140 ms gap means
Time inside the parent process before it made its first outbound call: deserialising the request, evaluating authorisation, waiting for a connection from a pool, waiting on a lock, or a stop-the-world pause. A gap in a waterfall is unattributed in-process work, not a network effect. It is the most commonly misread feature of a trace in production, because empty space looks like waiting on something external.
Check in this order
- Does the delta scale with concurrency? Then it is queueing. Look at the listen backlog and the worker-pool queue depth on the callee, not at its handler latency, which is healthy by construction.
- Is the delta constant? Then it is connection setup. A cold pool pays a TCP handshake plus one or two further round trips for TLS depending on the version negotiated. Inside one availability zone a round trip is well under a millisecond and between US coasts it is roughly 60 to 80 ms, so 160 ms inside a single region is not the network.
- Does the client span wrap retries? One client span covering two attempts shows a single slow call where there were two failed ones. Check the retry-count attribute before forming any other hypothesis.
- Then instrument the gap. A span around pool acquisition is usually one line of code and permanently ends this argument for that service.
When the numbers are not real
Client and server clocks differ. Across hosts, treat sub-millisecond differences as noise and never derive a one-way network time from two machines' timestamps. A child span that appears to start before its parent is a clock artefact rather than a causality violation, and chasing it wastes an afternoon.
Common weak answers
- "The callee is under-reporting its latency." It is reporting handler time honestly. The question is where the other 160 ms went, and the answer is in front of the handler.
- "Add a timeout." That changes who waits and for how long. It does not move the time.
- "The network is slow." Possible, and it is the fourth hypothesis rather than the first, because queueing and pool waits are more common and both are free to check.