Every timeout is checked twice: in a stream, and one at a time with a pause.
👋 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 reading mistake I made there, and the second run that catches it. Running notes live on my GitHub: github.com/brilliant-almazov.
This is how I work today, not a methodology - maybe you already do it better, maybe you'd do it another way entirely.
Two statements that are not the same statement
"This object does not get processed."
"This object did not get processed while two hundred others were going through next to it."
Those look like the same finding written twice. They are not.
The first is a property of the object: something about its data, its rules, its size makes the work fail.
The second is a property of the pace: the object is fine, the queue in front of it is not.
They lead to different work - one sends someone into the object's data, the other into the service's concurrency behaviour. Confusing them is expensive in the usual direction: a day spent looking for a broken object that was never broken.
A single run cannot tell them apart. That is the whole point of this part.
How I got it wrong
The run was a straight sweep: 276 operations back to back, as fast as the executor could issue them.
20-23 of them failed on time. And the failures were not scattered - they came in consecutive bursts, several neighbouring objects in a row, then a stretch of successes, then another burst.
My conclusion at the time: these objects do not rebuild. Twenty-three entities marked unfit, with the list to prove it.
The list was real. The conclusion was wrong.
Two things should have stopped me and didn't:
- The bursts. A defect belonging to objects has no reason to arrange itself by position in the run.
- The sample. I had exactly one measurement of each object, taken under exactly one condition.
The check that caught it
The second run was the same objects, in the same order, with two changes: one at a time, and a pause between calls.
21 of them succeeded immediately. The remaining 1-2 succeeded after a pause.
The same objects, at two paces
nothing changed between the runs except how fast the work was fed in
in a stream - 276 operations back to back, as fast as they could be issued
·······XXXXXXX··········XXXXXX·········XXXXX········XXXX··········
20-23 failed on time, in consecutive bursts · passed X failed
one at a time, with a pause - the same 23 objects, in the same order
·····················[·][·]
21 passed immediately, the remaining 1-2 after a pause [·] after a pause
A failure that disappears when the pace changes does not belong to the
object.
Same object. Same data. Same code path. Different pace, different result.
That is the whole inference, and it is a cheap one:
A failure that disappears when the pace changes does not belong to the object.
The object never changed between the two runs; only the traffic around it did.
The reverse case is just as useful. If an object fails in the stream and fails alone with a pause, the failure is the object's - and only then is it worth opening its data.
Cutting off "it's the volume"
The obvious next suspect is size: maybe the failing objects are the big ones, and big is slow.
The data disagrees. The failing objects range from 98 rows to 50 105 rows - the smallest and the largest in the vertical are both in the failure list. A size threshold would not put them there together.
So I measured the work directly instead of arguing about it:
| Data size | Storage calls | Time |
|---|---|---|
| 502 rows | 14 | 0.35 s |
| 50 117 rows | 15 | 1.33 s |
A hundred times the data, one extra storage call. The work is not per-entity: it reads in sets, so the number of round trips is a property of the algorithm, not of the row count. Time does grow - 0.35 s to 1.33 s - but that is the cost of moving rows, not a fan-out.
Across the vertical a single operation lands between 0.35 s and 1.58 s. Nothing in that range explains a failure at twenty seconds.
Volume is out.
Measuring the ceiling on concurrency
If it is not the object and not the volume, the thing left is how much work the service will do at once. That is measurable directly: issue the same operation from N callers in parallel and watch total time.
| Concurrent callers | Total time |
|---|---|
| 1 | 0.62 s |
| 2 | 0.88 s |
| 4 | 1.47 s |
| 8 | 9.68 s |
At eight, the median call took 5.77 s - and no call failed.
Read the shape rather than the numbers.
Up to four callers, total time grows roughly with the number of callers: work is taken in turn and the queue stays short. At eight, total time jumps to 9.68 s while a single operation still costs under 1.6 s - the eighth caller is not doing slow work, it is waiting for the seven in front of it.
That is the answer: the operations are executed one at a time. Concurrency does not buy throughput here; it buys a queue.
And that explains the bursts. In a straight sweep, an operation that lands behind a full queue waits, the next lands behind a longer one, and failures arrive as consecutive runs of neighbours - exactly the pattern I read as "these objects are broken".
The method that falls out of it
Every failure on time is checked twice: in a stream, and one at a time with a pause.
- Reproduces only in the stream → it is the queue. Fix the queue.
- Reproduces in both → it is the object. Now open its data.
- One run gives no verdict at all - in either direction.
That last line is the one I keep having to say out loud.
A single sweep produces a confident list of "broken objects" and no way to tell whether the list means anything. The second run is not extra rigour - it is the measurement that makes the first one readable.
What the trace shows, and what it doesn't
One detail worth naming here because it looks like evidence and isn't.
The failure arrives at exactly 20.00 s. That is a hard response deadline - the number is a property of the caller's patience, not of the work. Every failed call took precisely as long as it was allowed to take, which is why the failures look so uniform.
Inside that window, the time went into waiting. In a trace it shows up as an uncovered gap: a span that lasts the full window with nothing underneath accounting for it. Reading trace contents properly - what to put in a report and what to throw away - is the subject of Part 3.
What a calm pace produced
The same work, same production, same objects, issued with pauses instead of at full speed:
900 s for the whole vertical, 70 of 76 objects on the first attempt.
Fifteen minutes, and the work completes. Nothing was fixed between the failing run and this one - no code change, no data change. Which is the cleanest statement of the finding I have: the work is entirely doable; the question is only how fast it is fed in.
What it costs
Two costs, and I would rather name them than pretend the method is free.
The double check doubles the measurement. Every timeout costs two runs instead of one, and the "one at a time with a pause" run over a whole vertical takes about a quarter of an hour - fine for a suspicious result, too slow as the default for everything.
And "it's the queue" fixes nothing by itself. It is a re-address, not a repair: the question moves from which objects are broken to how much work may be submitted at once, and that one belongs to the design of the service. The measurement tells you which question to spend the week on. It does not answer it.
The part that generalises
A fast executor will happily hand you a list of broken objects, because a list is the cheap artefact: run once, collect failures, print. Nothing about those failures announces which of the two statements at the top of this article they support.
Telling a property of the object from a property of the pace takes a second run at a different pace, and nothing in the first run asks for one. So the requirement has to sit in the instruction:
Any failure on time is re-checked one at a time, with a pause, before it is reported as a property of the object.
Speed multiplies whatever discipline is already written down. It supplies none of it.
This is my current answer to a run full of timeouts, and the price of it is written above. I'd like to hear the other side: if you do this better, tell me how you separate load effects from object defects; if you have been through this, tell me what your bursts turned out to be; if you see it differently, say where the two-run rule breaks down. How is it solved on your side, and what broke there?
Testing production with an executor - Part 2.
Next: what actually belongs in a trace report - service, span name, duration, status text, and how many milliseconds of the window are covered by nothing at all - and why the trace ID is worthless an hour later.
Top comments (0)