Observability: Finding Why a Request Took 5 Seconds

A request took 4.7 seconds. Logs tell you it happened. They rarely tell you where the 4.7 seconds actually went: the database query, the payment call, a lock wait, or serialization. Observability is the difference between "something is slow" and "this specific call to this specific dependency is slow, and here is the trace to prove it."

The problem

A slow endpoint in a service with five downstream dependencies gives you one number (total latency) and a pile of log lines with timestamps you have to manually subtract to guess where the time went. That guessing gets worse, not better, as the system grows.

The naive approach

1log.info("Fetching order {}", orderId);
2Order order = orderRepository.findById(orderId);
3log.info("Order fetched");

Two log lines around a call tell you it started and it finished. They do not tell you how long the database query itself took versus connection pool wait time, and they do not connect to what happened in the payment service three log files away.

The production approach

Spring Boot's observability model rests on three pillars that share one identity: logs (what happened), metrics (how often and how fast), and traces (the causal chain across services), all tied together by the Micrometer Observation API and, downstream, an OpenTelemetry collector:

1management:
2  tracing:
3    sampling:
4      probability: 1.0
5  otlp:
6    tracing:
7      endpoint: http://otel-collector:4318/v1/traces
8  metrics:
9    distribution:
10      percentiles-histogram:
11        http.server.requests: true

With tracing enabled, the correlation ID from article 3 in this series and a proper distributed trace ID become the same concept, propagated automatically across HTTP calls Spring makes on your behalf. Individual methods worth watching get instrumented declaratively:

1@Observed(name = "order.fetch", contextualName = "fetch-order")
2public Order getOrder(Long orderId) {
3    return orderRepository.findById(orderId)
4        .orElseThrow(() -> new ResourceNotFoundException(orderId));
5}

For a code path that is not a full method, like one branch inside a larger operation, a manual observation gives the same tracing and timing without extracting a new method just to add an annotation:

1Observation.createNotStarted("inventory.check", observationRegistry)
2    .lowCardinalityKeyValue("sku.category", item.category())
3    .observe(() -> inventoryClient.getStock(item.sku()));

The result, viewed in a trace explorer: a single request to GET /orders/123 shown as a tree, with the API handler at the root and the database query, payment call, and Redis lookup as timed child spans. The 4.7 seconds resolves into "4.3 of it was one slow query" instead of a mystery.

Making it reusable

The management.tracing and management.otlp blocks are identical across every service in a fleet and belong in a shared Spring Boot starter or parent configuration, not copy-pasted per repository. Sampling probability is the one value worth tuning per environment: 1.0 (trace everything) in staging, something lower in production once traffic volume makes full tracing expensive.

Testing it

Observability code is easy to leave untested because it "just adds logging." The one thing worth actually asserting in a test is that a @Observed method still propagates its return value and exceptions correctly, since an incorrectly configured aspect can silently swallow both. Beyond that, this is verified by looking at real traces in a staging environment, not by unit tests.

What I learned

Observability is worth building before the incident that makes you wish you had it, not during one. Retrofitting tracing onto a system while it is actively on fire is a much worse experience than having it already running quietly in the background, at effectively zero marginal cost per request once the infrastructure exists.