Where Did the 200 ms Go?

Why are logs not enough?

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

gateway     10:30:00.104  order received, validated (8 ms)
risk        10:30:00.147  risk check passed (5 ms)
margin      10:30:00.201  margin reserved (11 ms)
bridge      10:30:00.298  sent to MT5 (9 ms)
bridge      10:30:00.331  fill received
gateway     10:30:00.344  returned to customer

Total "processing" time: 33 ms
What the customer waited:  240 ms
The missing 207 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.

Finding that with logs means comparing six timestamps by hand. 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 an afternoon's work and delivers most of the value immediately.

// 1) Gateway: as the request enters
String correlationId = request.header("X-Correlation-Id");
if (correlationId == null) correlationId = UUID.randomUUID().toString();
MDC.put("cid", correlationId);          // put it in the logging context

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

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

// 4) Restore it on the consumer side
MDC.put("cid", message.get("cid"));

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 need it.

The result: one search shows the whole journey.

$ grep 'cid=7f3a-991b' /var/log/*/app.log | sort -k1
# or on your log platform:  cid:"7f3a-991b"

10:30:00.104  gateway   order received
10:30:00.112  gateway   written to redis
10:30:00.301  risk      message received       ← a 189 ms GAP!
10:30:00.306  risk      check passed

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

Then the real thing: traces

A correlation ID answers "where". A trace goes one step further: it shows how long each step took and which step sits inside which.

trace_id: 7f3a...  "place order"                    240 ms
├─ gateway: validation                                8 ms
├─ gateway: redis xadd                                3 ms
├─ [WAITING IN QUEUE]                               189 ms   ← there it is
├─ risk: check                                        5 ms
│  └─ risk: postgres query                            3 ms
├─ margin: reservation                               11 ms
└─ bridge: send to MT5                               24 ms
   └─ bridge: TCP write                               9 ms

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:

// 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();

Sampling: do not trace everything

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

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:

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.
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. Tail sampling. 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 AI agent task list

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.