The labs on this site need JavaScript to run. The same content is written out below.

Learn › Architecture and operations › Observability

Distributed tracing

One request is slow, but which service is to blame?

One order request passes through the gateway, the order service, the payment service, and the external payment provider in turn. Logs pile up separately in each service, so without a common ID that ties together the logs of the same request, it is hard to find where the time went.

Checked against documentation and standards · The W3C Trace Context standard and the OpenTelemetry documentation

Concepts in this lab

Distributed tracing (trace ID, span)

A technique for tracking the whole path of a single request as it is processed across several services. A unique trace ID is assigned when the request first arrives, and it is passed along with every call between services. The segment handled by each service is called a span, and collecting the spans with the same trace ID shows which segment took the time.

Observability (logs, metrics, traces)

The ability to understand the internal state of a system from its external outputs alone. Logs are records of individual events, metrics are values aggregated as numbers, such as request counts and response times, and traces are records of the path one request takes through several services and the time spent in each segment. You need all three together to detect problems and find their causes.

MDC

A logging feature that automatically prints context information about the current request (such as the request ID and the user ID) with each log entry. It keeps values per thread: if you put the values in when a request starts, the same values appear in every log entry written by the thread that processes that request. Even when the logs of many requests are mixed together, you can pick out the logs of a single request.

APM

A tool that monitors the performance of an application. It collects and shows the response time of each request, which methods or queries took the time, the errors that occurred, and more. In Java, it is usually applied as an agent, with no code changes. Examples are Pinpoint, Scouter, and Datadog.

Monolithic architecture and microservice architecture

A monolithic architecture builds all features as one application and deploys them together. A microservice architecture splits the features into small services, and each one is developed, deployed, and scaled independently. With microservices, each service can be deployed and scaled separately and failures are isolated, but the complexity of communication between services, data consistency, and operations grows a lot.

Try these

• Default settings — The external payment provider is slow. You can see it at a glance on the tracing screen.
• Without a trace ID — Each service has logs, but you cannot connect the ones that belong to the same request.
• When the database query is slow — The slow span moves inside the order service.
• When the inside of the payment service is slow — The time of the payment service minus the time of its external call is long.

Running with the default settings

1. The request arrives at the gateway. It has no trace ID, so a new trace ID (4bf92f35…) is created. This ID goes along with the request until it ends. The gateway's processing is the first span.
2. When the gateway calls the order service, it puts the trace ID and its own span ID into the HTTP headers. The order service picks up the same trace ID and records its own processing as a new span (its parent is the gateway's span).
3. The order service queries the database (30ms). This query is recorded as a span too.
4. The order service calls the payment service. The trace ID is passed in the headers again. Each time a log is written, the trace ID held in the MDC is printed with it automatically.
5. The payment service calls the external payment provider API (2000ms). When the response comes back, the spans close in reverse order: the payment service, the order service, and the gateway. Total: 2095ms.
6. When you look up a single trace ID in the tracing system (Zipkin, Tempo, and so on), the five spans are drawn on a time axis in a staircase shape. The span with the longest self time (its inner calls excluded) is "Payment provider API". You can see right away where it is slow.

Result of this run

• A trace ID is a number attached to a whole request, and a span is one part of it (the processing of one service, one query, or one external call). Each span records its parent span, so the call relationships can be rebuilt as a tree.
• Logs tell you "what happened", metrics tell you "how much overall", and traces tell you "where and for how long for this request". If you also print the trace ID in the logs, you can find the slow span on the tracing screen and then search the logs by that ID.

Code

// build.gradle: Micrometer Tracing
implementation 'io.micrometer:micrometer-tracing-bridge-otel'

# Header added automatically when services call each other (W3C Trace Context)
traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
#               └─ trace id (same for the whole request)      └─ span id (differs for each span)

# Put the trace ID into the log pattern (taken from the MDC)
logging.pattern.level: "%5p [%X{traceId:-},%X{spanId:-}]"

Assumptions of this model

This is a simple structure in which four services are called in turn, and the times are example values. The trace ID, the span, and the way they are propagated in headers follow the explanations in the W3C Trace Context standard and the documentation of OpenTelemetry and Micrometer Tracing. In practice, not every request is recorded in many cases, and only a sample is collected.

Previous lab: Averages and percentiles · Next lab: Merge and rebase