A service is judged by its own span, not by the client's stopwatch.
👋 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 one write path that left the monolith and what it took to accept it as working. This part is about latency: where it actually sits, and how long we argued about it before anyone measured. 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 path in one paragraph
One feature: a user saves a set of matching rules, and every domain under that account gets marked according to them. Four participants. The Go API gateway is the only door from outside. The rule-set-markup service takes the write, folds the cascade and persists it. The domain-rule-map service owns rule-set identity and does the recalculation, with a worker process behind a queue. Storage is PostgreSQL - the monolith's database for the rule data, the domain-rule-map service's own for identity.
One user action, four processes, two databases. When it is slow, everyone in the chain has an opinion about whose fault it is, and none of the opinions cost anything to hold.
The call everyone argued about
A single write, traced end to end: 121 spans, four services, 1 256.9 ms as seen by the client.
The blame went to the write service, because that is the one the request is addressed to. Here is the same call as nesting, which is the only shape that answers the question:
client wait 1 256.9 ms 100 %
├── transport, client ↔ environment 244.9 19.5 % not ours
└── gateway root 1 012.0 80.5 %
├── auth, rate limit, identity, cache 3.7
├── own work + 4 SQL + one catalog call 47.4
└── batch write call 950.9
├── hop, gateway → write service 7.9 not ours
└── rule-set-markup 943.0
├── own work 1.4
├── validate + gather, 5 SQL 32.3
├── identity calls → domain-rule-map 76.7
├── its own transaction, 10 SQL 54.4 (SQL 53.7 · work 0.7)
└── recalculation → domain-rule-map 775.6
└── worker: canonicalise 350.9
├── SELECT dictionary rows 129.6
└── INSERT dictionary rows 112.5
The service under suspicion owns three rows of that tree: its own work, its validate/gather step and its transaction. 87.4 ms out of 1 256.9 - 7.0 % of what the client waited. And inside those 87.4 ms, 98.4 % is waiting on PostgreSQL; the code itself accounts for 1.4 ms.
Two things worth saying out loud about that tree:
- Never sum nested spans. 943.0 already contains 775.6, which already contains 350.9. Adding them up is how a 1.2-second call becomes "three seconds of work".
- The whole call cost 53 database round trips, 11 of them repeats of a query already made in the same call. That count, not the milliseconds, is the actionable number - and I'll come back to it.
The rejected request that settled the zone question
Arguments about "the network is fine, it's your service" ended with the cheapest measurement in the whole set: a request that was rejected as invalid.
POST … → 422 Unprocessable Entity
server work 6.6 ms
database 0.0 ms
client wall 231.8 ms
─────────────────────
225.2 ms, or 97.2 % of the call, is not the service
The server parsed a body, failed validation and answered in 6.6 ms. The client saw 231.8 ms. Nothing was computed, nothing was stored, and 97 % of the call still happened outside our code.
That is not a defect and it is not fixable by us - the environment sits at a steady 220-260 ms regardless of endpoint or payload size, confirmed on a rejection and on a full run. It only becomes a lie when someone quotes the client's stopwatch as a service metric.
So the reading rule for the whole series, written down after this:
A service is judged by its root and server spans.
walldescribes the trip, not the work.
Three builds, one input
The same read request - two domains, one account - run three times on three consecutive builds of the matching service, same day:
- client wall: 715.9 → 324.0 → 433.1 ms
- server root: 474.7 → 76.2 → 59.1 ms
- database total: 440.0 → 37.2 → 31.8 ms
- database queries: 92 → 7 → 7
- network: 242.1 → 250.1 → 381.3 ms, i.e. a share of 33.8 % → 77.2 % → 88.0 %
Read the network share alone and the story is "it got dramatically worse: the network went from a third of the call to almost all of it". Read the row above it and the story is the opposite: the part we own fell by a factor of eight, and the part we don't own never moved.
wall 715.9 ╲___324.0 ╱‾433.1 the trip bounced around
server root 474.7 ╲______76.2 ╲_59.1 ◄ what we own — fell monotonically
database 440.0 ╲______37.2 ╲_31.8 ◄ 14× drop
queries 92 ╲_________7 ─── 7 ◄ the shape of the query is what got fixed
network 242.1 ─────250.1 ╱‾381.3 ░ not ours — our fix did not move it
Hence the second rule, which I now apply to every chart in this material: a share is never published without its absolute value. 440.0 ms · 61 %, never 61 %. A percentage of a moving denominator is the easiest honest-looking way to say the wrong thing.
What build A was actually doing
Build A was not slow because the database was slow. It was slow because of the shape of the work:
- one compile step held 411.1 ms - 91 % of the server window;
- inside it, a per-rule resolver ran 86 times;
- each of those read the rule-type catalog: 88 identical
SELECT … ORDER BY idin one call.
The response was correct the whole time. Status 200, right data, PASS on content - and a class of defect that no response code can express. It was caught in one call for exactly one reason: the spans carried the query text, so 88 identical statements were visible as 88 identical statements, not as "the database was busy".
The fix moved it to 7 queries. And with the database gone from the picture, the slowest remaining participant became the network - which is the correct end state, not a regression.
The other direction: when the wait has no name
The opposite case, from the write path, same period: recalculation calls started failing on a 20-second deadline - first on 13 of 76 objects, then, after a change meant to help, on 27 of 76.
The instinct was to look at the write transaction. The transaction took 14.8 ms.
The time was in two spans nobody had thought about:
- queue wait: 64-84 s - work sitting in a queue before anyone started it;
- one canonicalisation lookup: 32.3 s.
Neither is "the service being slow". Both are the service waiting, and the only reason they were nameable is that somebody had instrumented the wait before it became a problem. The four places a request sits still - acquiring a connection, waiting for a worker, handing work over, waiting for the answer - are almost never covered by a span, which is why they show up as an unexplained gap.
What the traces still do not show
Honest inventory, because a measurement set with unknown holes in it is worse than one with known holes.
- transport, client ↔ environment - measured: steady 220-260 ms, not ours.
- hop between services - measured as a gap: 0.8-2.4 ms per transition, 7.9 ms on the write call.
- the service's own work - measured: its own spans, per service.
- database - measured: per query, with the statement text and a repeat count.
- gRPC encode / decode - not measured: unknown, probably small, but not a measured zero.
The gap is real: between-service time is derived from where the child span starts, so serialisation, deserialisation and whatever the client library does around them are folded into one number that nobody has split. On the numbers above it cannot be large. That is a bound, not a measurement, and I keep it in the list rather than pretending it is zero.
Why this is an SLO conversation, not a performance one
Once the zones are separated, the chain stops being a mystery and starts being arithmetic:
chain response ≈ the slowest participant + everything spent between them
That reframes every argument we had:
- a service's target belongs to its own span, because that is the only part its team can move;
- the door's target is the sum plus the hops, and it is the only number a user experiences;
- the environment gets an explicit line - 220-260 ms of it here - so it is never mistaken for someone's fault;
- and the sensible unit for a per-service budget is often not milliseconds but round trips: 53 database calls with 11 repeats, or 92 queries where 7 will do.
None of that needs new infrastructure. It needs the zones to be separable in the data you already collect - and one line in the report saying which zone each number belongs to.
The multiplier line
An automated executor made this cheap: run, pull the trace, fold it into a table, run again on the next build, print the difference. What it did not do was decide what counts as ours. That distinction - our span, the environment, the database, the unmeasured gap - is a judgement, and it is the whole value of the exercise. Speed of measurement amplifies whoever set the definitions; it does not supply them.
Anatomy of a service split — Part 1. Next: the same run produced numbers nobody could have predicted from the code, because the services had endpoints that could describe their own state. That is the next part - what a service has to expose before anyone can check it.
If you do this better, tell me how you draw the line between your zone and the environment. If you have been through this, what did your unexplained gap turn out to be? If you see it differently, say where per-zone budgets cost more than they return. How is it solved on your side, and what broke there?
Top comments (0)