Distributed Tracing With OpenTelemetry

In lesson 2 a metric told us that p99 latency was high. That is useful, but it is not an answer. Which service is slow? Which call? A request in a modern system may pass through a gateway, three services, a cache and a database. If the whole thing took 318 ms, who used the time?

This is lesson 3 of nine. Lesson 0 introduced traces as the third pillar. Here we make them. We use OpenTelemetry (often written OTel), an open standard and set of libraries for producing traces, metrics and logs. We run two real local services, watch the trace id travel between them in an HTTP header, read the spans, and then tie traces back to logs. The next lesson, SLIs, SLOs and Error Budgets, turns all this data into reliability targets.

You need basic Node.js and HTTP. An HTTP Server From Scratch is enough background.

Words used in this lesson

• A trace is the full record of one request as it moves through a system.
• A span is one timed unit of work inside a trace, such as an HTTP call or a database query.
• Trace id is the unique id shared by all spans of one trace. Span id is the id of one span.
• Parent span is the span that caused another. A span with no parent is the root span.
• Attributes are key and value facts attached to a span, like http.response.status_code = 200.
• Events are timestamped notes inside a span, like "cart validated".
• Span kind says the role of the span: server (handling an incoming call), client (making an outgoing call), internal, producer and consumer (for queues).
• Status of a span is unset, ok or error.
• Context is the bag of "current trace" information that follows your code as it runs.
• Context propagation is moving that context between processes, so spans in different services join one trace.
• traceparent is the standard HTTP header that carries the trace id and parent span id.
• Instrumentation is code that creates spans. Auto-instrumentation is a library that does it for you for common packages (http, express, database drivers).
• An exporter sends finished spans somewhere. OTLP is OpenTelemetry's own network format for sending telemetry.
• A collector is a separate program that receives telemetry, processes it and forwards it to storage.
• Sampling is deciding which traces to keep.
• A resource describes who produced the telemetry, such as service.name.

What a trace looks like

The OpenTelemetry docs explain traces with a small example of three spans, and I like it because it is so plain. A request starts the first span, called hello. It has a trace id and a span id, and it has no parent, so it is the root. Inside it there is a span hello-greetings, which carries the same trace id but has a parent_id equal to the span id of hello. The parent link and the shared trace id are the entire data model. Everything else is detail.

trace id = T  span A  (parent: none)            <- root    span B  (parent: A)      span C  (parent: B)    span D  (parent: A)

Each span records a name, a start time, an end time (so a duration), a kind, attributes, optional events and a status. From many spans with the same trace id you can rebuild the tree and see who waited for whom.

Here is a real one. I started two services: a gateway on port 5001 and an inventory service on port 5002. The gateway calls inventory over HTTP, then does a short render step. Inventory runs a fake database query that takes about 30 ms (or 300 ms when the URL has slow). I sent two requests, and then printed the spans with a small script:

trace fe586f8dae8982f18591f1aab4919b3f  GET [gateway, SERVER] start +0ms dur 88ms    GET [gateway, CLIENT] start +4ms dur 68ms      GET [inventory, SERVER] start +25ms dur 45ms        db.query [inventory, INTERNAL] start +27ms dur 31ms    render [gateway, INTERNAL] start +74ms dur 10mstrace fbb307353101cc69c23c041113679dc0  GET [gateway, SERVER] start +0ms dur 318ms    GET [gateway, CLIENT] start +1ms dur 305ms      GET [inventory, SERVER] start +3ms dur 307ms        db.query [inventory, INTERNAL] start +3ms dur 301ms    render [gateway, INTERNAL] start +307ms dur 10ms

Read the second trace as a story. The gateway received a request that took 318 ms in total. It spent almost all of it waiting for its call to inventory (305 ms). Inventory spent 307 ms handling it. And inside inventory, 301 ms went to db.query. The render step is just 10 ms. So the slow part is the database query. That tells you where to look in a few seconds, without reading any logs.

Also notice the numbers in the first trace: the client span in the gateway (68 ms) is longer than the server span in inventory (45 ms). The difference of about 23 ms is time on the network, in the HTTP client and in the server before the span started. That is a free hint about overhead between the services, and it is one of the nice things about having both a client span and a server span for each call. (The first request in a fresh process also pays one-off costs such as opening a connection, so do not over-read one trace.)

How the trace id crosses the network

This is the part people find magic, so let us look at the actual bytes. When the gateway's code makes an HTTP call, the instrumentation adds a header to the outgoing request. I wrote a small test where a client with tracing makes a request, and a plain server prints the headers it receives:

client root span  : 01981deb85e0955b56c737a554da810f dddd7f8929e0d301server saw traceparent: 00-01981deb85e0955b56c737a554da810f-58a8fcb504e84011-01server saw tracestate: undefined

The header is called traceparent and has four parts separated by dashes: a version (00), the trace id (32 hex characters), the parent span id (16 hex characters), and flags (01 means "sampled"). The trace id in the header (01981deb...) is the same as the one my client started. The span id in the header (58a8fcb5...) is not the root span id (dddd7f89...). It is the id of the HTTP client span that the instrumentation created under the root, which is the span that is actually making the call. That is correct: the server's span becomes a child of the client span.

On the receiving side, the instrumentation reads traceparent, and starts its server span with the same trace id and with the parent set to that span id. That is context propagation, in full. It is a standard (the W3C Trace Context standard), which is why services written in different languages and traced by different vendors can still join one trace.

And what if the caller has no tracing at all? I ran a plain client with no SDK and the server printed:

traceparent: undefined

No header. So if the receiving service has tracing it will start a new trace with a new id, and you end up with two unconnected traces for what was one request.

There is a second header, tracestate, for vendor-specific extra data. In my run it was not set, which is normal.

Setting up OpenTelemetry in Node.js

You need three groups of packages: the API (what your code calls), the SDK (the implementation that records and exports), and instrumentations (code that creates spans for libraries). I installed these:

@opentelemetry/api@1.9.1@opentelemetry/sdk-node@0.223.0@opentelemetry/sdk-trace-base@2.12.0@opentelemetry/instrumentation-http@0.223.0@opentelemetry/exporter-trace-otlp-http@0.223.0

The API and the SDK are split on purpose. Library authors use only the API. If no SDK is installed, the API does nothing and costs almost nothing. The application owner installs the SDK and decides where data goes. I measured this: creating 200,000 spans with only the API (no SDK) cost about 0.46 microseconds per span; with the SDK running and a batching processor that sent to a do-nothing exporter, about 3.0 microseconds per span. These are tiny numbers on my machine, and a real exporter that sends data over the network adds more, but they show that tracing is not heavy if you sample sensibly.

The setup file

OpenTelemetry must be started before your application code loads the libraries it wants to instrument. So we put the setup in its own file and load it with --require. Here is mine, with a small custom exporter that writes one JSON line per finished span into a file:

// tracing.cjsconst { NodeSDK } = require("@opentelemetry/sdk-node");const { HttpInstrumentation } = require("@opentelemetry/instrumentation-http");const { SimpleSpanProcessor } = require("@opentelemetry/sdk-trace-base");const { appendFileSync } = require("node:fs");class FileExporter {  export(spans, done) {    for (const s of spans) appendFileSync("spans.jsonl", JSON.stringify({      service: process.env.OTEL_SERVICE_NAME, name: s.name, kind: s.kind,      traceId: s.spanContext().traceId, spanId: s.spanContext().spanId,      parentId: s.parentSpanContext?.spanId ?? null,      startMs: s.startTime[0] * 1e3 + s.startTime[1] / 1e6,      durMs: s.duration[0] * 1e3 + s.duration[1] / 1e6,      status: s.status.code, attrs: s.attributes }) + "\n");    done({ code: 0 });  }  shutdown() { return Promise.resolve(); }}new NodeSDK({  spanProcessors: [new SimpleSpanProcessor(new FileExporter())],  instrumentations: [new HttpInstrumentation()],}).start();

I start each service with its name in an environment variable:

OTEL_SERVICE_NAME=inventory node --require ./tracing.cjs svc.cjsOTEL_SERVICE_NAME=gateway   node --require ./tracing.cjs svc.cjs

OTEL_SERVICE_NAME is a standard environment variable. The service name is vital, because it is what lets a tracing tool show "gateway" and "inventory" as separate boxes. When I forgot to set it in another test, the resource said unknown_service:node, which is the fallback, and it makes everything look like the same service.

A word on the span processor: I used SimpleSpanProcessor, which exports each span as soon as it ends. That is good for a demo, and bad for production, where you want BatchSpanProcessor. It collects spans and sends them in groups, so your request path does not wait for the network.

Manual spans

Auto-instrumentation gives you the HTTP spans for free, but your own business steps need manual spans. In the inventory service I wrapped the fake query like this:

const { trace } = require("@opentelemetry/api");const tracer = trace.getTracer("shop-demo");await tracer.startActiveSpan("db.query", async (span) => {  span.setAttribute("db.system", "fake");  span.setAttribute("db.statement", "SELECT stock FROM items WHERE sku=?");  await sleep(30);  span.end();});

startActiveSpan does three things: it creates a span, makes it the active one for the code inside the callback (so any span created inside becomes its child, and any outgoing HTTP call carries it), and gives you the span to finish. You must call span.end(). A span that never ends is never exported, and it silently disappears.

How does the "active span" follow your code across await? Node's AsyncLocalStorage, the same tool we used for request ids in lesson 1. OpenTelemetry's context manager for Node uses it under the hood. That is why you do not pass the span around by hand.

What the real spans contain

Here is one auto-created server span from inventory, shortened (real output; the long attribute list is trimmed):

{"service":"inventory","name":"GET","kind":1, "traceId":"fe586f8dae8982f18591f1aab4919b3f","spanId":"74199df71baf62ce","parentId":"2113c6203b44935d", "durMs":44.5,"status":0, "attrs":{"http.request.method":"GET","url.path":"/stock","server.port":5002,"http.response.status_code":200}}

Look at parentId: 2113c620.... That is exactly the span id of the gateway's client span for this request, which proves the link across the process boundary. And kind: 1 is SERVER. The attribute names such as http.request.method and http.response.status_code follow OpenTelemetry's semantic conventions, which are agreed names, so every tool understands them. Use them where they exist instead of inventing your own.

Spans carry more than time

A trace that only shows durations is useful. A trace that also shows what went wrong is better. A span can record:

• Attributes (facts about the work): cart.items = 3, db.system = postgresql, http.response.status_code = 500.
• Events (things that happened at a moment inside the span): "cart validated", or an exception.
• Status: set to error when the operation failed.

I sent a small trace through the real OTLP exporter to my local receiver, with an error inside it:

tracer.startActiveSpan("checkout", { attributes: { "cart.items": 3 } }, (span) => {  span.addEvent("cart validated");  tracer.startActiveSpan("charge-card", (child) => {    try { throw new Error("card declined"); }    catch (e) { child.recordException(e); child.setStatus({ code: SpanStatusCode.ERROR, message: e.message }); }    child.end();  });  span.end();});

The receiver printed that it got one request and its size, and I decoded the JSON body:

POST /v1/traces application/json 3436 bytesresource service.name: { stringValue: 'unknown_service:node' }{"name":"charge-card","traceId":"37599358101937ae5bbe08f9a7322fd9","spanId":"3048c599c49c6ca7","parent":"6b011476f078e82f","status":{"code":2,"message":"card declined"},"events":["exception"],"attrs":[]}{"name":"checkout","traceId":"37599358101937ae5bbe08f9a7322fd9","spanId":"6b011476f078e82f","status":{"code":0},"events":["cart validated"],"attrs":[{"key":"cart.items","value":{"intValue":3}}]}

So the OTLP exporter sent an HTTP POST to /v1/traces with a JSON body of 3,436 bytes. The charge-card span has status.code: 2, which means ERROR, with the message "card declined", and an exception event (that holds the type, message and stack). Its parent is the span id of checkout. The checkout span has the attribute cart.items as an integer and the event "cart validated".

A tracing tool shows the error span in red, and you can click to see the exception. This is how you go from "it was slow" to "this step failed".

Propagation beyond HTTP: queues and jobs

HTTP instrumentation injects and extracts the header automatically. For anything else (a message queue, a job, a custom protocol), you do it by hand with the propagation API. You inject the current context into the message's headers when you send, and extract it when you receive. Here is a small real run that simulates a queue with a plain object:

const message = { body: "order 7001", headers: {} };propagation.inject(context.active(), message.headers);// ... the message travels through the queue ...const parentCtx = propagation.extract(ROOT_CONTEXT, message.headers);context.with(parentCtx, () => tracer.startActiveSpan("worker.process", (w) => { /* work */ w.end(); }));

message headers: { traceparent: '00-7cc8bf51bde92805e38cdc458c46dda4-17b0a9f4c38a2ca2-01' }worker parent == handle-order span? true same trace? true

The message carries the same traceparent as an HTTP call would. The worker's span became a child of handle-order in the same trace. Without the inject and extract step the worker would start a brand new trace.

For queues, OpenTelemetry has two ways to connect work: a normal parent-child link when the consumer is a direct continuation, and span links when many messages are batched into one job, so one span points to many origins. For a first setup, parent-child is fine.

Tying traces and logs together

In lesson 1 we put a request id on every log line. With tracing you can use the trace id instead. The result is that you can jump from a slow trace to every log line written inside that trace.

With pino it takes a few lines in mixin:

const log = pino({ mixin() {  const s = trace.getActiveSpan(); if (!s) return {};  const c = s.spanContext(); return { trace_id: c.traceId, span_id: c.spanId };} });

And the real output, from the run that also passed context through the simulated queue:

{"level":30,"msg":"outside any span"}{"level":30,"trace_id":"7cc8bf51bde92805e38cdc458c46dda4","span_id":"17b0a9f4c38a2ca2","msg":"inside the span"}{"level":30,"trace_id":"7cc8bf51bde92805e38cdc458c46dda4","span_id":"e4cc0916b063abb1","msg":"worker log line"}

The first line, written outside any span, has no ids. The second and third lines carry the same trace_id, even though the third was written by the "worker". Search your logs for that trace_id and you see everything that happened for that request, across both. (OpenTelemetry also has a logs signal and a logs bridge for pino that does this link for you. I did not run that one here, so I show the simple, manual version that I did run.)

This closes the loop from lesson 0: a metric alert, then a slow trace, then the logs of that trace.

Sampling: you cannot keep everything

If every request makes 20 spans and you serve 1,000 requests per second, that is 20,000 spans per second. Storing them all is costly. Sampling decides which traces to keep. There are two main styles.

Head sampling decides at the start of the trace, at the root, before anything is known. It is simple and cheap. For example "keep 10 percent". I ran this with OpenTelemetry's TraceIdRatioBasedSampler(0.1) inside a ParentBasedSampler, creating 10,000 traces, each with a root span and one child span:

{ rootsKept: 1029, childrenKept: 1029, spansTotal: 2058 }

About 10 percent of the traces were kept (1,029 out of 10,000; random sampling varies a little). And the important thing: children were kept exactly when their root was kept, 1,029 each. That is what the parent-based wrapper does: the first service decides, and everyone downstream follows the decision (the flags 01 or 00 at the end of traceparent carry it). You never get half a trace.

The downside of head sampling: you decide before you know whether the request will be slow or fail. At 10 percent you may throw away the one trace you needed.

Tail sampling decides at the end, once the whole trace is seen. You can say "keep all traces with an error, all traces slower than 1 s, and 5 percent of the rest". That is better for debugging, but it needs a place that collects all spans of a trace before deciding, typically the OpenTelemetry Collector, which costs memory and money. I did not run a Collector in this lesson, so I only describe tail sampling here.

A sensible start: head sample at a modest rate in the application, keep the default parent-based behaviour, and consider tail sampling when you run a Collector and need to keep the errors.

Reading a trace: a small method

When you look at a trace to find a problem, follow these steps:

1. Find the longest span at the bottom. The slowest leaf is often the cause. In the trace above it was db.query at 301 ms.
2. Compare parent and child durations. If a parent is 305 ms and its only child is 45 ms, the gap (260 ms) is time spent in the parent: waiting, queueing, or work that is not traced. Add a span there.
3. Look for gaps between spans. Idle time between two child spans can mean waiting for a lock or a connection pool.
4. Look for a wide row of similar short spans. One request making 200 database calls in a row is the N+1 query pattern. Each call may be fast; together they are slow.
5. Check parallel versus serial. If three calls could run together but the trace shows them one after another, you have easy savings.
6. Check status and events. An error span or an exception event tells you the failing step.

What goes wrong in practice

• Broken propagation. The trace is cut at a proxy, queue or old service. Fix by forwarding traceparent and by using inject and extract for non-HTTP hops.
• Missing span.end(). The span never appears. Use try/finally.
• ESM instrumentation not applying. As I found, test that auto-instrumentation produces spans.
• No service name. Everything shows as unknown_service:node.
• High-cardinality span names. Name spans by the operation (GET /users/:id), not by data (GET /users/8231). Put the id in an attribute.
• Sampling too low. You cannot debug what you did not keep. Keep errors if you can.
• Too many spans. A span for every tiny function makes traces unreadable and costs more. Span the boundaries (incoming request, outgoing call, database, queue), not every function.
• Clock differences. Spans on different machines are ordered by each machine's clock. If clocks differ by a few milliseconds, children can appear to start before parents. Use time sync (NTP).
• Sensitive data in attributes. See the warning above.

Try it

1. Create two small Node HTTP services, A and B. A calls B. Start both with a tracing.cjs like the one in this lesson and OTEL_SERVICE_NAME set. Make a request to A and print the spans from your exporter. Do they share a trace id? What is the parent of B's server span?
2. Add a manual span work of about 100 ms inside B. Where does it appear in the tree?
3. Make B slower by 200 ms. Look at the trace: how can you see from the durations of A's client span and B's server span that most time was spent in B and not on the network?
4. Start B without --require ./tracing.cjs. What does the trace look like now? Why?
5. Add the trace id to your pino logs using mixin. Make a request and use the id to find all log lines for it.
6. You have a service with 2,000 requests per second, 15 spans per request, and each span is about 400 bytes. How much trace data per hour if you keep everything? And with 5 percent head sampling?
7. A trace shows parent span 800 ms, and its children are 100 ms and 120 ms. Where might the other 580 ms be?

Answers

1. Yes, they share a trace id. B's server span has as its parent the span id of A's HTTP client span, not A's root span.
2. Under B's server span, as a child (it was created while that span was active).
3. A's client span is only a bit longer than B's server span (for example 305 ms against 307 ms or so in my run, or a small positive difference). If most of the time were on the network, the client span would be much longer than the server span.
4. A's trace shows the client span, but B's spans are missing, or B starts a separate trace if it has some tracing but no header handling. Without the SDK B does not read traceparent and creates no spans.
5. Search your logs for the printed trace_id. You should see all lines written in that request, in both services if both have the mixin.
6. 2,000 × 15 = 30,000 spans per second. At 400 bytes that is 12 MB per second, or about 43 GB per hour (12 MB × 3,600). At 5 percent: about 2.2 GB per hour.
7. In the parent itself: untraced work (computation, serialisation), waiting for a lock or pool, an await on something with no span, or sequential gaps. Add spans there.

Interview questions

Key takeaways

• A trace is a tree of spans sharing one trace id, with parent links. A span has a name, timing, attributes, events and a status.
• Context propagation moves the trace id between services in the traceparent header (version-traceid-parentspanid-flags). If a hop drops it, the trace breaks.
• In my real run, a 318 ms request was traced to a 301 ms db.query span in another service, in seconds.
• Use the API in libraries and the SDK in applications. Start the SDK before the code it instruments, and set OTEL_SERVICE_NAME.
• Always call span.end(), name spans by operation, use the standard attribute names, and keep secrets out of attributes.
• For queues and jobs, inject the context into the message and extract it in the worker. A mistake there fails silently.
• Put trace_id and span_id in your log lines to link traces and logs.
• Sample on purpose. Parent-based head sampling kept 10 percent of traces and never half a trace. Tail sampling keeps the interesting ones but needs a collector.

What's next

Next: SLIs, SLOs and Error Budgets, Lesson 4. We now have logs, metrics and traces. The next question is what level of reliability is good enough, and how to measure it. You will learn how to choose an indicator, set an objective, turn "three nines" into minutes, and calculate a burn rate, with a script and with the Prometheus data we collected. Practise now: add tracing to two small services of your own and find which of them is slower using only the trace.