Sertaç Yıldırım field notes

Home → Engineering

Where Did the 200 ms Go?

Customers are complaining: orders sometimes open late. We measured — 240 ms end to end. Four services, and each one says in its own log "I finished my part". Their own numbers add up to 40 ms. Where are the other 200?

Sertaç Yıldırım · · 9 min read

Summary
  • The sum of each service's own time is not the real time. Time disappears in the gaps between them.
  • A correlation ID is the cheapest win. Even without full tracing, add it today. But carry it across thread pools and clear it when the work ends.
  • The trace must cross queues too. Otherwise the trail breaks halfway.
  • You do not have to trace every request. But always keep the slow and failing ones, and every service must read the sampling decision the same way.

Why are logs not enough?

We had logs from four services and each was correct in its own way:

Four services, six lines, no single truth 
gateway     10:30:00.112  order validated (8 ms)
gateway     10:30:00.115  written to redis (3 ms)
risk        10:30:00.320  risk check passed (5 ms)
margin      10:30:00.331  margin reserved (11 ms)
bridge      10:30:00.344  MT5 fill received (13 ms)
gateway     10:30:00.344  returned to customer

What the services report: 8+3+5+11+13 = 40 ms
What the customer waited:              240 ms
The missing 200 ms: ???

The lost time is not inside the services but between them: waiting in a queue, waiting for a connection from the pool, network, serialisation, and the sneakiest one — queueing for a thread.

The gap is actually in the timestamps above: from .115 to .320 is 205 ms (including risk's own 5 ms; pure waiting is 200 ms). But to see it you have to put the logs of four machines side by side and subtract by hand. Easy for one request. At 50,000 requests a second, when you do not even know which line belongs to which request, it takes hours. And server clocks drift by milliseconds, so the difference you compute can occasionally come out negative.

First, the cheapest thing: a correlation ID

Building full tracing takes time. But carrying a single identifier through the whole system is a day's work and delivers most of the value immediately.

The rule: generate at the entry point, carry everywhere, clear when done 
// 1) Gateway: as the request enters
String cid = request.header("Correlation-Id");     // the X- prefix is deprecated (RFC 6648)
if (cid == null || !cid.matches("[A-Za-z0-9-]{8,64}")) {
    cid = UUID.randomUUID().toString();            // never trust an external header as-is
}
MDC.put("cid", cid);                               // put it in the logging context

// 2) Carry it on HTTP calls
httpClient.header("Correlation-Id", cid);

// 3) CARRY IT IN QUEUE MESSAGES TOO  ← the most skipped step
redis.xadd("orders", Map.of("cid", cid, "payload", json));

// 4) Restore it on the consumer side, clear it when the work ends
String incoming = message.get("cid");
if (incoming == null || !incoming.matches("[A-Za-z0-9-]{8,64}")) {   // same check: the gateway is not the only writer
    incoming = "none-" + message.id();
}
MDC.put("cid", incoming);
try {
    process(message);
} finally {
    MDC.remove("cid");   // a pooled thread must not carry the old cid into the next message
}

Step three is critical. Most teams carry it in HTTP headers but drop the chain the moment work goes onto a queue. Yet in asynchronous systems most of the time is spent exactly there — so you lose the trail precisely where you must not lose it.

The finally in step four is not decoration either. MDC is thread-local: when work moves to an executor, a CompletableFuture or any other thread pool, cid does not follow on its own; you need an executor wrapper that copies it. And if you do not clear it, a thread that returns to the pool sticks the old cid onto the logs of an unrelated request. The result: customer A's logs carry customer B's id. This is a real production bug, and it takes weeks to notice.

The validation in step one matters for the same reason. If you put an external header into your logs as-is, with no length or character limit, someone can send you a newline and write fake lines into your logs (log injection).

The result: one search shows the whole journey.

Now possible 
$ grep -h 'cid=a91c-4d02' /var/log/*/app.log | sort
# -h: hide the file name, otherwise the first field is "path:timestamp", not the timestamp
# or on your log platform:  cid:"a91c-4d02"

10:30:00.104  gateway  cid=a91c-4d02  order received
10:30:00.115  gateway  cid=a91c-4d02  written to redis
10:30:00.315  risk     cid=a91c-4d02  message received   ← a 200 ms GAP!
10:30:00.320  risk     cid=a91c-4d02  check passed

There is the 200 ms. After the order was written to the Redis stream, it took the risk service 200 ms to pick it up. The cause: the risk service ran a single consumer and a large batch order was ahead of it — classic head-of-line blocking.

Reaching that conclusion through logs alone would have taken days. With a correlation ID it took fifteen minutes.

Of all observability investments, the correlation ID has the highest return. A day of work that pays for itself the first time you use it.

Then the real thing: traces

A correlation ID answers "what happened, in which order". A trace goes one step further: it shows how long each step took and which step sits inside which.

Two concepts, that is all
  • Trace: the whole request. One trace_id.
  • Span: a single piece of work inside it. Each span has a start, a duration and a parent.
trace_id: 7f3a...  "place order"                    240 ms
├─ gateway: validation                                8 ms
├─ gateway: redis xadd                                3 ms
┆  ··· gap: waiting in queue ···                    200 ms   ← there it is
├─ risk: check                                        5 ms
│  └─ risk: postgres query                            3 ms
├─ margin: reservation                               11 ms
└─ bridge: send to MT5                               13 ms
   └─ bridge: TCP write                               9 ms

This view does in one glance what four log files side by side cannot: it makes the gap visible.

Two notes. First: there is no span called "waiting in queue" that appears on its own. That line is the gap between the end of the redis xadd span and the start of the risk: check span; the trace tool shows it as empty space in the tree, and you give it a name. Second: span durations are reliable, because each one is measured on its own machine's clock. The gap between spans is the difference between two machines' clocks — clock drift exists here too. A few milliseconds of drift will not hide a 200 ms gap; but do not make decisions based on a 5 ms gap.

Joining the two sides of a queue

This is the most critical detail of tracing in asynchronous systems. You have to inject the trace context into the message when producing, and continue from it when consuming:

Carry the context with the message 
// Producer side
Map<String,String> carrier = new HashMap<>();
propagator.inject(Context.current(), carrier, Map::put);
redis.xadd("orders", merge(payload, carrier));   // traceparent inside the message

// Consumer side
Context parent = propagator.extract(Context.root(), message, GETTER);
Span span = tracer.spanBuilder("risk check")
                  .setParent(parent)              // ← the chain does not break
                  .startSpan();
try (Scope s = span.makeCurrent()) {             // child spans attach under this one
    riskCheck(message);
} finally {
    span.end();                                  // a span that is never ended is never exported
}

Skip this and every consumer starts a new trace, leaving you with hundreds of short unrelated traces. Technically you have deployed tracing; practically you can answer no question.

Batch consumption is different: if the consumer takes 100 messages at once, there is no single parent, because 100 messages have 100 different traces. A span can have only one parent. OpenTelemetry's advice here is addLink instead of setParent: the batch span links to every message's context, and you can jump from any message's trace to the batch.

How do the two ids live together?

You have seen two separate ids above: cid and trace_id. They are not the same thing, and this is where the most common confusion starts.

  • If you are setting up OpenTelemetry, do not invent a separate correlation header. W3C traceparent is already the standard; the trace_id inside it is unique per request. Put it in MDC, print it on every log line as trace_id, and you do not need a cid. The Correlation-Id header at the start of this post does not contradict this: you set it up today because OpenTelemetry takes months; when OTel arrives, trace_id takes over as the request id, and you keep cid only as the business-flow id described below.
  • If the business flow is longer than one request, carry both. The order opens, the fill arrives at the end of the day, reconciliation runs the next morning: three requests, three traces. What connects them is a business id (like order_id) or a cid that travels with the whole flow. The rule: trace_id = one request, cid = one business flow. Print both on the log line, as two separate fields.

Sampling: you do not have to trace every request

In a system doing 50,000 operations a second, recording every request is neither sensible nor cheap. But sampling 1% at random is not enough on its own — because what you care about is not the average request but the bad one.

Tail sampling

The right approach is to decide after the request finishes:

  • It errored → keep 100%
  • It took over 100 ms → keep 100%
  • Specific customers / VIP accounts → keep 100%
  • Everything else, normal requests → keep 1% (for a baseline)

Cost stays low and every problematic request is in your hands. "The customer complained but that request was not sampled" is the most frustrating way to have tracing.

It has a price. Because the decision is made after the request ends, all spans of one trace must arrive at the same collector instance: the load balancer must route consistently by trace_id, and the collector must hold spans in memory until it decides. At 50,000 requests a second, that makes the collector layer a system of its own. The hard part of the setup is here, not in the sentence "keep the slow ones".

How does the sampling decision spread across services?

If you cannot run tail sampling, the decision is made at the entry point (head sampling) and travels to downstream services in the sampled flag, the last two characters of traceparent (01 keep, 00 drop). If one service ignores the flag and rolls its own dice, you get half traces: present in the gateway, missing in risk, present again in margin. This is the most common cause of "we set up tracing but the traces come out incomplete". The rule: the decision is made in one place, and everyone follows the flag. If you plan tail sampling, the opposite applies: the edge service must always send 01 (AlwaysOn), otherwise a slow request marked 00 at the edge never reaches the collector and cannot be recovered later.

Three common mistakes
  • Putting large data in spans. Attaching the whole order as JSON bloats the trace store and gets expensive. Put identifiers only: order_id, symbol, an internal id that does not point directly at the customer.
  • Exporting synchronously on the request path. When the collector slows down, your application slows down. Export must always be in the background, and it must drop when the buffer is full — the observability tool must never block the real work.
  • Writing personal data into spans. Customer names, emails, account numbers — trace stores are usually less protected than logs.

Keeping all three together

Metrics, logs and traces are three views of the same problem. The real power comes from being able to move between them:

ToolQuestion it answersWhere it leads
MetricsIs there a problem?"p99 latency is 240 ms" → to a trace
TracesAt which step?"200 ms in the queue" → to the logs
LogsWhat exactly happened?"single consumer, batch ahead of it"

For that chain to work you need one thing: every log line must carry trace_id. If you can jump from a slow trace to that request's logs with one click, your setup is doing its job; if you have to copy the id and search by hand, half of it is missing.

Where to start

  1. Correlation ID. Today. Everywhere, including queues; carry it across thread pools, clear it when the work ends.
  2. Structured logs. Fields instead of free text; cid and trace_id as their own fields.
  3. Tracing on the critical flow. Do not instrument everything at once; put it on the order path and see the value.
  4. Sampling. Start with head sampling and services that follow the flag; move to tail sampling once the collector layer is in place. Slow and failing requests at 100%.
  5. Expand. Once the value is proven, extend to other flows.

The first two steps solve most of your problems even without any tracing infrastructure. Projects that start with "let us set up OpenTelemetry first" are usually still setting it up six months later; a correlation ID works the next day.

Checklist

Observability
  • Does every request carry a correlation ID?
  • Is that id carried in queue messages too?
  • Does the id follow work into thread pools, and is MDC cleared when the work ends?
  • Does every log line have trace_id and (if used) cid as separate fields?
  • Does the trace chain join both sides of a queue?
  • Is every span ended in a finally?
  • Are slow and failing requests kept at 100%?
  • Do all services read the sampled flag the same way?
  • Are spans free of large payloads and personal data?
  • Does trace export run in the background?
  • Can you go from metric to trace to log by clicking?

Conclusion

In a distributed system the most expensive thing is the hours spent not knowing where the problem is. The code fix is usually ten minutes; finding it takes days.

That 200 ms was not a bug; it was a single-consumer queue. Nobody wrote bad code, nobody did anything wrong — nobody could see the whole. And that is the only thing tracing does: it makes the gaps between the pieces visible.