Why a 2.4-second request can contain 2.8 seconds of spans

The caller waited 2.4 seconds. Add up the recorded operations and you get 2.8. Nothing has traveled backward in time: two lookups were running together, and the sum counted their shared time twice.

Put the operations on one timeline and the discrepancy becomes useful. It shows where work overlapped and leaves a smaller, more interesting question about time the recorded operations do not explain.

Here is a synthetic Dispatch request. Every time is measured in milliseconds from the request's start, using the same clock basis.

Span	Start	End	Duration
Request	0	2400	2400
Lookup A	200	1200	1000
Lookup B	300	1500	1200
Write result	1600	2200	600

Each row is a span, a record of an operation's start and finish. The request is the root span: it has no parent in this trace. The other three are its children. That relationship says which request they belong to. Their timestamps tell us whether they were open at the same time.

Count the shared nine hundred milliseconds once

The child durations add up to 2,800 milliseconds. But lookup A starts at 200, lookup B starts at 300, and the last of them finishes at 1500. Together they cover one continuous 1,300-millisecond interval. The write covers another 600 milliseconds, separately. Child spans therefore cover 1,900 milliseconds of the request's elapsed time.

Both lookups are open from 300 through 1200. Adding their individual durations counts those 900 milliseconds twice. Moving along one time axis counts them once, which matches the caller's experience: they waited through that interval only once.

Do not read those rectangles as CPU usage. A lookup may spend much of its span waiting for another service. The trace tells us when the operation was open, not how busy a processor or thread was throughout it.

There are also three intervals outside the child spans: 0–200, 1500–1600 and 2200–2400. Together they make 500 milliseconds. Application work, scheduling or missing instrumentation might explain them. The blank space locates a question; it does not supply its cause.

Follow that interval, or an operation that changed, toward another check. The largest rectangle is not automatically the answer.

A faster lookup might leave the caller waiting just as long

Draw a second synthetic request. This time B ends at 2300, the write runs from 2400 to 3000 and the request ends at 3200. B appears to hold up the write. Before treating that ordering as a dependency, check whether the application really waits for B's result. Parent-child relationships alone do not prove it.

Look at the attributes, errors and related logs for this same request. One selected slow request cannot tell us that every tenant has the same problem.

Now shorten lookup A in the drawing but leave B's finish at 2300. If the write requires both results, it still waits for B. We have improved A's number without getting the customer to the end any sooner.

Code, or an event recording that both lookups finished, could support this explanation. If the write actually waits for an unrelated timer, the visible ordering would mean something else. The drawing gives us a reason to investigate the dependency; the dependency determines what an improvement can change.

The request can finish before its background job

An export request may receive its acceptance reply before the export even starts. Passing the identifiers that connect its records, called trace context, lets us follow both pieces without pretending the API waited for the entire job.

Some relationships do not fit a single parent. A batch assembled from several messages can use span links to record its connections to those inputs. Linking the later batch does not lengthen the earlier API response.

Our arithmetic uses one consistent clock basis. Real hosts can disagree about the time, making apparent ordering misleading. Corroborate the timestamps and how the instrumentation records operations before using that order as proof.

Leave the unexplained half-second visible

Draw the four intervals on one axis. Mark the 1,900 milliseconds covered by children, then the remaining 500. Choose one possible explanation for a gap and an observation that would distinguish it from another explanation. If you suspect CPU work, for instance, a profiler or an extra span might help.

The request now fits its actual 2.4 seconds. Overlap accounts for the oversized sum; the half-second outside the child spans remains open for investigation. The next note can name that interval and the observation needed, without filling it with work the trace never recorded.

Sources

OpenTelemetry traces explains spans, context and links. These intervals are synthetic teaching data.