A trace ID is useless an hour later; what survives is the spans, their durations and the uncovered window.
👋 Hi, I'm Anton - a software engineer working mostly in PHP/Symfony and Go, currently carving a live PHP monolith into Go services. This series is about checking that migration against production with an executor doing the runs. This part is about one habit that cost me a day and has been written into the instruction ever since. Running notes live on my GitHub: github.com/brilliant-almazov.
This is how I do it right now, with the price attached - maybe you already do it better, maybe you'd do it another way.
The identifier is not the evidence
A run finishes, a call failed on time, and the report says: failed, trace <identifier>.
That line looks complete. It isn't. An hour later it is worth nothing at all, for three separate reasons:
- The retention window has passed. Traces are kept for a short period by design; the identifier outlives the data it points at.
- The time window has moved on. Whoever opens the tracing system now has to reconstruct when the run happened before they can look at anything.
- The reader may not have access. A report is read by people who were not in the run - and sometimes by people who have no account in that system.
So the identifier stays in the report, but demoted: it is a pointer to the source, not the finding. The finding is the contents.
What exactly gets saved
For every span in the failed call, the report carries five fields:
| Field | Why it is there |
|---|---|
| service | which side of the call the time belongs to |
| span name | which step it was |
| duration | how long that step took |
| status code | whether the step failed |
| status message | why it failed, in words |
And then one line the five fields do not give you:
how many milliseconds of the window are covered by spans, and how many are covered by nothing at all.
That line is the one I would keep if I could keep only one.
First failure mode: the work never started
The first shape looks like this. The trace has no span from the executing service at all. The only thing in it is the call span, and its status message reads timeout acquiring a connection.
That single sentence is the whole diagnosis: the time went into getting a connection. The work was never handed to the service, so the service has nothing to be slow at.
Now notice what is left if the status message is dropped:
- duration - the full window;
- status code - failed;
- service - the callee.
By code and duration alone this is indistinguishable from "the service computed for twenty seconds and gave up" - which sends someone into the service's query plans for a day, looking for slow work that never ran.
The text of the status is not decoration. It is the field that separates two opposite verdicts.
Two traces, one symptom
both calls fail at 20.00 s - the contents of the trace tell them apart
failure mode 1 work never started
┌───────────────────────────────────────────────────────────────────┐
│ call span · 20 000 ms │
└───────────────────────────────────────────────────────────────────┘
status: timeout acquiring a connection
no span from the executing service - the empty row is the point
failure mode 2 the service waited
┌───────────────────────────────────────────────────────────────────┐
│ executor span · 20 000 ms │
└───────────────────────────────────────────────────────────────────┘
███ storage calls · 40 ms total
19 960 ms with no child span at all
By code and duration alone the two are the same failure. The status
message is what separates them.
Second failure mode: the arithmetic
The second shape has spans in it, and it is the more interesting one.
The executing service's span lasts 20 000 ms. Inside it, its own storage calls add up to 40 ms.
Do the subtraction out loud, because that is the entire method:
executor span 20 000 ms
storage calls inside 40 ms
-----------------------------------
covered by nothing 19 960 ms (99.8% of the window)
Nineteen point nine seconds inside that span belong to no child span whatsoever.
For scale, a normal operation of this kind lands between 0.35 s and 1.58 s and makes 14-15 storage calls. So the failing case is not "the same work, only more of it" - the work it did do is a rounding error against the window it occupied.
The conclusion is one sentence: the service was waiting, not computing. And it is available without a profiler, without extra instrumentation, without reproducing anything - from two numbers already in the trace.
Where the 20 000 ms went
one span of the failing call, and the part of it that has a name
executor span · 20 000 ms hard deadline 20.00 s
┌─┬───────────────────────────────────────────────────────────────────┐
│█│ 19 960 ms covered by nothing · 99.8% of the window │
└─┴───────────────────────────────────────────────────────────────────┘
└── storage calls · 40 ms
a normal operation of this kind, on the same scale
┌────┐
│████│ 0.35 - 1.58 s · 14-15 storage calls
└────┘
The window is not full of slow work. It is full of time that has no name
yet.
The uncovered window as a measurement
That subtraction generalises into one number worth carrying in every trace report:
the share of the root span's duration that is not covered by any child span.
While that share is large, there is nothing to discuss about why it was slow. The waiting has no name yet. Any answer at that point is a guess dressed as a finding - and it will be a guess about the wrong component, because the component with the visible spans is the one that gets blamed.
The measurement also points at the fix, and the fix is not in the report - it is in the service:
Instrument the waits first. Four of them, in order:
- acquiring a connection;
- waiting for a free worker;
- handing the work over;
- waiting for the response.
Those are the places where a request sits still, and they are exactly the places that usually carry no span - spans get written around the code someone is proud of.
Every span added to a wait converts uncovered milliseconds into a named step. That is the whole goal: drive the uncovered share down until the largest remaining block has a name.
The number that is too round to be a measurement
One more reading, cheap and easy to miss.
The failure arrives at exactly 20.00 s. Not 19.4, not 21.7 - 20.00, on every failed call.
A duration produced by work is never that tidy. A round number is a limit, not a result: it is the hard response deadline, and it is not set by the caller. Every failed call took precisely as long as it was allowed to take.
So when the durations in a report cluster on a round number, the object under test is not the thing to look at first. The limit is. The work was cut off there; the trace says nothing about how much longer it would have run.
How this lands in the instruction
The executor doing these runs works from a written instruction - what goes into that instruction is Part 1 of this series. This part changed exactly one line in it.
The line used to mean attach the trace. It now means:
Pull the contents of the trace and put them in the report: per span - service, name, duration, status code, status message; plus covered and uncovered milliseconds of the window. The identifier goes in as a source reference.
The difference between those two versions is not stylistic. Under the first one the report is formally complete and factually empty: it has an identifier for every failure and not one statement about where the time went. Nobody notices at hand-off, because at hand-off the trace is still there and everyone remembers the run.
What it costs
Extracting contents is a separate step and separate code. The trace has to be fetched, parsed, and folded into a table of service / span / duration / status - and then the covered-versus-uncovered arithmetic has to be done on it. On a single run that is real work for a report nobody may open.
It pays off only across several runs. If the check will happen once, the honest answer is that the identifier plus a screenshot at the time is cheaper. If it will happen weekly, the extraction is written once and every later report is readable without access to anything.
I'd rather name that trade-off than pretend the discipline is free.
The part that generalises
An executor brings back exactly what it was asked for, quickly and consistently. "Attach the trace" and "attach the contents of the trace" are one word apart, and they produce two different reports - one that answers questions next week and one that doesn't.
The gap between them is invisible at the moment of delivery. It shows up a week later, when someone reads the report and finds a list of identifiers pointing at data that no longer exists. Speed multiplies whatever the instruction says. It does not improve the instruction.
This is my current answer to a report full of failed calls, and the price of it is written above. I'd like to hear the other side: if you do this better, tell me what your trace reports carry; if you have been through this, tell me what your uncovered window turned out to be; if you see it differently, say where storing contents instead of pointers costs more than it returns. How is it solved on your side, and what broke there?
Testing production with an executor - Part 3. That closes this block: the instruction, the two-run rule for timeouts, and what a trace report has to carry.
Next I go back to the start of the chain - the class of problem that sends you looking at traces in the first place: an empty screen that is not a failure, and how to tell a missing result from a result that was never supposed to exist.
Top comments (0)