Overview / Transaction tracing
Transaction tracing
Carrying one identity through six systems
Tracing is not really a timing problem. Timing a piece of work is easy. The hard part is that the work changes shape as it travels — it becomes a message, then a row, then a request to somebody else — and something has to survive all of those changes so the pieces can be put back together at the end.
Gateway
Where the request first becomes yours. The identifier is minted here, or accepted from whoever called you.
Authentication
The check that decides whether this transaction is allowed to continue at all, and on whose behalf.
Application
Your own code: the business rules, the orchestration, the branch that only runs for certain orders.
Database
Reads and writes — and the time spent waiting for a free connection rather than waiting for the query.
External call
Anything you do not run. Timed from your side of the boundary, because that is the only side you have.
Rendering
Assembling the answer and getting the last byte of it out of the door.
Correlation identifiers
The whole method rests on one value: an identifier created once, at the first place the work becomes yours, and then attached to every subsequent piece of work descended from it. Everything else — the timings, the hop names, the parent and child relationships — is reconstruction after the fact, and it only works if this value was carried faithfully.
Three properties matter, and only three. It has to be unique enough that two unrelated transactions cannot collide within the window you keep data for. It has to be cheap to generate without asking a central service for permission, which in practice means a large random value rather than a counter. And it has to be opaque: an identifier that encodes a customer number or an account is a piece of personal data that you have just written into every log line on the estate.
The commonest failure is not a bad identifier. It is a good identifier that gets recreated halfway through, because a component received a request without one and helpfully minted a fresh one rather than complaining. The transaction then arrives at your storage as two separate short traces that look perfectly healthy on their own. Decide early whether a missing identifier is an error or a silent new start, write that decision down, and make the two cases distinguishable afterwards.
Propagating context across a boundary
A boundary is anywhere the work stops being a function call. An outbound network request, a message onto a queue, a job written into a table for a worker to pick up later, a callback from somebody else's system, a scheduled batch that processes yesterday's rows. Each one needs a deliberate answer to the same question: where does the identifier ride?
Over a synchronous protocol the answer is usually a header, and the mechanics are simple because there is an obvious place to put one. The awkward cases are the asynchronous ones. A queue may not have a metadata field, in which case the context has to go inside the message body, which means changing the message format, which means every consumer has to tolerate the new field before any producer emits it. A batch job that reads a table has no message at all, so the identifier has to have been stored in the row when it was written, hours earlier.
There is also an in-process boundary that catches almost everyone: handing work to another thread. Context that lives in thread-local storage does not follow a task into a pool, so the child work starts life with no parent and appears at the top of your data as an orphan. If you see a population of very short root traces with names that look like internals, this is nearly always what happened.
Our position on all of this is that propagation should be boring and explicit. Where a boundary cannot carry context, we would rather show a broken chain honestly than stitch two traces together on a guess about timing, because a plausible wrong join is far more expensive than a visible gap.
Sampling, and the trace you did not keep
Instrumenting a transaction is cheap. Keeping every transaction forever is not. Sampling is the compromise, and choosing where in the pipeline to make the decision changes what you are able to answer later.
| Approach | When the decision happens | What it costs you |
|---|---|---|
| Keep everything | Never; nothing is dropped | Storage and network grow with traffic. Honest, and often unaffordable at the top of the estate. |
| Decide at the start | At the first hop, before the work runs | Cheapest, and the decision is made before anything interesting has happened — so the rare failure is exactly as likely to be dropped as a boring success. |
| Decide at the end | After the transaction finishes, on what it did | Keeps the slow and the failed. Requires holding every unfinished trace somewhere until it completes, which moves the cost rather than removing it. |
| Decide by name | Per transaction type, set by hand | Lets you keep all of a rare, important operation and little of a chatty one. Needs maintaining, and goes stale when someone adds a new operation. |
The arithmetic of a start-of-transaction sample is worth stating plainly, because it is frequently misunderstood. If you keep one transaction in every hundred, you keep one in every hundred — including one in every hundred of the failures. When somebody reports a problem that affects a handful of transactions a day, the chance that any one of them is in your data is small, and no amount of querying will conjure it back.
That is the real cost of sampling, and it is paid at the worst possible moment: the one time you needed the one trace you did not keep. The mitigations are unglamorous. Keep the counts of everything even when you drop the details, since counts are tiny. Keep a full record of anything that ended in an error, whatever the sample rate says. And give the people investigating a way to raise the rate for one transaction type for an afternoon without a deployment.
Clock skew between machines
A trace made of spans from several machines is a claim about a shared timeline, and no such timeline exists. Each machine has its own clock, each one drifts, and each one is corrected by a time service in small jumps that are invisible to your application. Two clocks agreeing to within a few milliseconds is a good day. Across a wide area, or on a machine whose time service has quietly stopped, the disagreement can dwarf the thing you are trying to measure.
The visible symptoms are recognisable once you know them. A child span that appears to begin before its parent. A network call whose duration measured at the caller is shorter than the work measured at the receiver, which is arithmetically impossible. Two spans that overlap when the code makes overlapping impossible.
The defensible response is to trust a duration far more than an instant. A duration measured by a single machine using a monotonic clock is reliable, because it never involves comparing two clocks. An instant — and therefore any gap computed by subtracting one machine's timestamp from another's — carries the skew of both. So we lay traces out using each span's own measured duration, show cross-machine gaps as gaps rather than as precise figures, and flag impossible orderings instead of silently reordering them into something that looks tidy.
What a trace cannot see
- Time before the identifier existed: connection setup, the queue in front of your gateway, and everything that happened on the user's own device or network.
- Work inside a system you do not run, which arrives as one opaque duration with no structure inside it.
- Contention for shared resources. A transaction that waited because a neighbouring process was using the processor looks identical to one that was simply doing more work.
- Anything a library does without emitting a span, including retries, which frequently hide inside what appears to be a single call.
- The transactions that never arrived at all. Traces describe what happened, and are silent about what a user gave up on before starting.
None of these are reasons to skip tracing. They are reasons to be careful about the sentence “the trace shows”, which should always be followed by what was actually measured rather than by what the measurement is being taken to mean.
Questions that come up early
How many spans should one transaction produce?
Enough to name every hop where the work could plausibly get stuck, and no more. A useful test: if a span were to double in duration, would somebody know what to do? If not, that span is costing you overhead and storage to tell you nothing. Instrumenting every function in a call stack produces traces that are technically complete and practically unreadable.
What should a span be named?
After the operation, not after the code. A name that survives a refactor is worth much more than one that describes the current class layout, because the value of historical data comes entirely from being able to compare it with today.
Should the identifier appear in log lines too?
Yes, and it is the cheapest useful thing on this page. Once every log line carries the transaction identifier, the log and the trace become two views of one event rather than two unrelated piles of text, and an investigation stops with a search instead of a guess.
What about transactions that span days?
A booking that waits overnight for a human decision is one business transaction and it is not one trace. Model the waiting explicitly as its own state rather than as a very long span, otherwise every duration you compute is dominated by how long somebody took to read an email.
Does this need a change to every service at once?
No, and attempting it usually stalls. A partially traced estate still answers useful questions, provided the parts that are traced are the boundaries where work most often gets lost. Start at the edge, then follow the transactions that hurt most.
Once transactions are being traced faithfully, the next question is what to compare them against. That is the job of a baseline.