Distributed Tracing

The idea in one minute#

A trace is the story of one request as it crosses services. It is made of spans: each span is one timed operation with a name, a start, a duration, attributes, and a pointer to its parent. All spans of one request share a trace ID.

The whole mechanism rests on one thing: every service must pass the trace ID and its own span ID to the next service — context propagation — normally in an HTTP header called traceparent. Break the chain anywhere and you get two unrelated half-traces.

An analogy#

A parcel with a tracking number. Every depot scans it and records “arrived 09:02, left 09:40” against the same number. Later you can lay the scans end to end and see that the parcel spent four hours in one warehouse. The tracking number is the trace ID; each scan is a span; the sticker on the parcel is context propagation.

A picture#

flowchart LR
  C["Client"] -->|"traceparent: 00-TRACE-a1-01"| GW["Gateway<br/>span a1"]
  GW -->|"traceparent: 00-TRACE-b2-01"| API["Inference server<br/>span b2, parent a1"]
  API --> Q["queue<br/>span c1"]
  API --> PF["prefill<br/>span c2"]
  API --> DC["decode<br/>span c3"]
  GW -.->|"spans"| COL["Collector"]
  API -.->|"spans"| COL
  COL --> STORE[("Trace store")]
  class C neutral
  class GW,API compute
  class Q queue
  class PF,DC compute
  class COL io
  class STORE memory

How it really works#

A span#

trace_id        4bf92f3577b34da6a3ce929d0e0e4736     16 bytes, same for the whole request
span_id         00f067aa0ba902b7                     8 bytes, unique per span
parent_span_id  a1b2c3d4e5f60718                     empty for the root span
name            POST /v1/chat/completions            low-cardinality: the operation, not the URL
kind            SERVER | CLIENT | INTERNAL | PRODUCER | CONSUMER
start, end      timestamps
status          UNSET | OK | ERROR
attributes      http.response.status_code=200, gen_ai.request.model="...", ...
events          timestamped points inside the span ("first token")
links           references to spans in other traces (batches, fan-in)

A trace viewer draws spans as a waterfall: bars on a time axis, nested by parentage. Gaps between a parent and its children are time the parent spent itself — often a queue.

Context propagation: the W3C traceparent header#

traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
             │  └────────── trace ID ──────────┘ └── parent ID ──┘ └ flags (01 = sampled)
             └ version

• An incoming request with this header → your span joins that trace as a child.
• No header → you start a new trace.
• Every outgoing call → you write the header with your span ID as the parent.

Baggage is a second header for key-value pairs that should travel with the request (tenant=acme), so that deep services can attach them to their own spans.

Propagation is not only HTTP. The same context must travel through gRPC metadata, message queue headers, and — where traces most often break — across goroutines, thread pools, queues and batchers inside a process. An inference server that batches eight requests into one forward pass has one operation serving eight traces: model it with span links.

Sampling#

Recording every span of every request is rarely affordable.

The sampled flag in traceparent tells downstream services the head decision so the trace is kept or dropped as a whole. IV.04 covers the economics.

Getting from a metric to a trace: exemplars#

When a histogram records an observation while a sampled span is active, it can store that span’s trace ID next to the bucket. A latency graph then shows dots you can click to open an actual slow request. Enable exemplars: they are the cheapest bridge between “p99 is up” and “here is one”.

What to put on spans#

• Boundaries first: one span per incoming request, one per outgoing call (database, another service, a model).
• Phases that can each be slow: queue, auth, retrieval, prefill, decode.
• Attributes you will filter by: tenant, model, route, status, token counts.
• Not every function. A span costs a few hundred bytes and some CPU; ten thousand per request is a profiler’s job (lesson 04).

Reading a trace#

1. Find the longest bar that has no long children: that is where the time went.
2. Look for gaps — parent time not covered by children. Usually waiting.
3. Look for repetition: forty sequential database calls (the N+1 pattern), or an agent calling a model in a loop.
4. Look for fan-out: many parallel children; the slowest one decides the parent.

Code#

A tracer in sixty lines, with real traceparent propagation across an HTTP hop.

// trace.go — spans, parent/child links and W3C traceparent propagation.
package main

import (
	"context"
	"crypto/rand"
	"encoding/hex"
	"fmt"
	"net/http"
	"net/http/httptest"
	"strings"
	"sync"
	"time"
)

type Span struct {
	TraceID, SpanID, ParentID, Name string
	Start                           time.Time
	Dur                             time.Duration
}

type ctxKey struct{}

var (
	mu       sync.Mutex
	finished []Span
)

func id(n int) string {
	b := make([]byte, n)
	rand.Read(b)
	return hex.EncodeToString(b)
}

// Start begins a span as a child of whatever span is in ctx (or as a new trace).
func Start(ctx context.Context, name string) (context.Context, func()) {
	s := Span{SpanID: id(8), Name: name, Start: time.Now()}
	if p, ok := ctx.Value(ctxKey{}).(Span); ok {
		s.TraceID, s.ParentID = p.TraceID, p.SpanID
	} else {
		s.TraceID = id(16)
	}
	return context.WithValue(ctx, ctxKey{}, s), func() {
		s.Dur = time.Since(s.Start)
		mu.Lock()
		finished = append(finished, s)
		mu.Unlock()
	}
}

// Inject writes the current span into an outgoing request.
func Inject(ctx context.Context, h http.Header) {
	if s, ok := ctx.Value(ctxKey{}).(Span); ok {
		h.Set("traceparent", fmt.Sprintf("00-%s-%s-01", s.TraceID, s.SpanID))
	}
}

// Extract reads an incoming traceparent so the server's span joins the caller's trace.
func Extract(ctx context.Context, h http.Header) context.Context {
	p := strings.Split(h.Get("traceparent"), "-")
	if len(p) != 4 {
		return ctx
	}
	return context.WithValue(ctx, ctxKey{}, Span{TraceID: p[1], SpanID: p[2]})
}

func main() {
	// "Inference server": extracts context, records three child spans.
	backend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		ctx, end := Start(Extract(r.Context(), r.Header), "server: POST /v1/chat")
		defer end()
		for _, phase := range []struct {
			name string
			d    time.Duration
		}{{"queue", 12 * time.Millisecond}, {"prefill", 30 * time.Millisecond}, {"decode", 90 * time.Millisecond}} {
			_, endPhase := Start(ctx, phase.name)
			time.Sleep(phase.d)
			endPhase()
		}
	}))
	defer backend.Close()

	// "Gateway": starts the trace and propagates it.
	ctx, end := Start(context.Background(), "gateway: route request")
	req, _ := http.NewRequestWithContext(ctx, "POST", backend.URL, nil)
	Inject(ctx, req.Header)
	fmt.Println("sent header  traceparent:", req.Header.Get("traceparent"))
	resp, err := http.DefaultClient.Do(req)
	if err == nil {
		resp.Body.Close()
	}
	end()

	// Print the waterfall.
	root := finished[len(finished)-1]
	depth := map[string]int{root.SpanID: 0}
	fmt.Printf("\ntrace %s\n", root.TraceID)
	for i := len(finished) - 1; i >= 0; i-- { // parents finish last, so walk backwards
		s := finished[i]
		d := depth[s.ParentID] + 1
		if s.ParentID == "" {
			d = 0
		}
		depth[s.SpanID] = d
		fmt.Printf("  %s%-28s +%5.1f ms  %6.1f ms\n", strings.Repeat("  ", d), s.Name,
			float64(s.Start.Sub(root.Start).Microseconds())/1000, float64(s.Dur.Microseconds())/1000)
	}
}

Delete the Inject call and run it again: the server’s spans start a second, unrelated trace. That is the most common tracing bug in production.

Remember this#

• A trace is a tree of spans sharing a trace ID; a span is one timed operation.
• It works only if every hop propagates context — across the network and inside the process.
• Sample deliberately: head sampling is cheap, tail sampling keeps what matters.
• Exemplars connect a metric spike to an actual trace.

Try it#

1. Run trace.go, then remove Inject. How many traces are there now?
2. Run the three phases in separate goroutines. Does the context still reach them? Make it.
3. Add head sampling at 10% that honours the sampled flag end to end.

Check yourself#

1. What four things does a traceparent header carry?
2. Where inside a single process do traces most often break?
3. Why does tail sampling need to buffer whole traces?