Distributed Tracing

Metadata

1. Overview

What problem does it solve?

Logging tells you what happened. Monitoring tells you how many times it happened. But what if a single user request takes 5 seconds, and that request hits 12 different microservices?

If the user complains about a slow checkout, how do you find out which of the 12 microservices was the slow one? Reading the logs of 12 different services and trying to guess which log lines belong to that specific user's request is impossible.

Distributed Tracing solves this. It assigns a unique ID (a Trace ID) to a request the moment it enters the system. That ID is passed in the HTTP headers to every downstream service. A centralized UI (like Jaeger or Datadog) pieces those logs together to draw a beautiful visual timeline (a Gantt chart) showing exactly how long the request spent in every service.

What breaks without it?

• The Microservice Murder Mystery: When a request fails deep in a call chain (A -> B -> C -> D), Service A returns a 500 Error. Without tracing, developers spend hours pointing fingers at each other trying to figure out if B, C, or D caused the crash.

2. Motivation

In 2010, Google published the Dapper paper, describing their internal system for tracing requests across thousands of servers. This paper birthed the modern tracing movement.

Twitter open-sourced Zipkin, and Uber open-sourced Jaeger. However, instrumenting code was annoying because every tool had a different API. The industry eventually united under the OpenTelemetry (OTel) standard, creating a universal, vendor-neutral API for generating traces.

3. Real-World Usage

4. Prerequisites

5. Visual Explanation

The Anatomy of a Trace

• Trace: The entire journey of a single user request through the system.
• Span: A single logical unit of work within a Trace (e.g., a DB query, an HTTP call).
• Context Propagation: The act of passing the Trace ID to downstream services via HTTP headers.

%%{init: {'theme': 'base', 'themeVariables': { 'primaryColor': '#ffcc00', 'edgeLabelBackground':'#ffffff'}}}%%
gantt
    title Trace ID: abc-123-xyz (Total: 400ms)
    dateFormat  x
    axisFormat %s ms
    
    section API Gateway
    Span A (Gateway)        :0, 400
    
    section Order Service
    Span B (Auth Check)     :10, 50
    Span C (HTTP to Inv.)   :50, 200
    Span F (Save to DB)     :200, 390
    
    section Inventory Svc
    Span D (Check Cache)    :60, 80
    Span E (Query DB)       :80, 190

In this UI, it is instantly obvious that the bottleneck is Span E (Query DB in the Inventory Service), taking 110ms.

6. Internal Working

Context Propagation (W3C Standard)

How does Service B know it's part of Service A's trace? The W3C Trace Context standard dictates how headers should be passed over HTTP.

When the API Gateway receives a request, it generates a UUID and adds it to the HTTP header: traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01

1. 00: Version
2. 4bf92f...: Trace ID (Identifies the entire request tree).
3. 00f067...: Parent Span ID (Identifies the specific caller).
4. 01: Flags (e.g., Should we sample/record this trace?).

When Service A calls Service B, it reads this header, creates a new Span ID for itself, and passes the Trace ID and the new Span ID to Service B.

Behind the scenes, every service asynchronously ships these "Spans" (with start and end timestamps) to a Jaeger server. Jaeger matches them up by Trace ID and Parent Span ID to draw the UI.

7. Implementation

Why Python? Python's contextvars and simple HTTP mocking make it very easy to demonstrate how Trace IDs are extracted from headers, attached to logs, and passed downstream.

"""
034 - Distributed Tracing
A simulation of Context Propagation and Span creation across
three mock microservices (Gateway -> Order -> Inventory).
"""
import uuid
import time
import json
from contextvars import ContextVar

# A ContextVar is like thread-local storage, but works for async tasks too.
# It holds the current Trace Context so we don't have to pass it into every function.
current_trace_id = ContextVar('trace_id', default=None)
current_span_id = ContextVar('span_id', default=None)

# Mock Jaeger server that collects all Spans
trace_collector = []

class Span:
    """Represents a unit of work."""
    def __init__(self, name):
        self.name = name
        self.trace_id = current_trace_id.get()
        self.parent_span_id = current_span_id.get()
        self.span_id = str(uuid.uuid4())[:8] # Generate an 8-char hex ID
        
        # Make THIS span the new parent for any nested operations
        self.token = current_span_id.set(self.span_id)

    def __enter__(self):
        self.start_time = time.time()
        print(f"[{self.trace_id}] ▶ Start Span: {self.name} (ID: {self.span_id}, Parent: {self.parent_span_id})")
        return self

    def __exit__(self, exc_type, exc_val, exc_tb):
        self.end_time = time.time()
        duration_ms = (self.end_time - self.start_time) * 1000
        print(f"[{self.trace_id}] ⏹ End Span  : {self.name} ({duration_ms:.1f}ms)")
        
        # Ship span to the collector (Jaeger)
        trace_collector.append({
            "trace_id": self.trace_id,
            "span_id": self.span_id,
            "parent_id": self.parent_span_id,
            "name": self.name,
            "duration_ms": round(duration_ms, 1)
        })
        
        # Reset context back to parent
        current_span_id.reset(self.token)

# ── Microservices ──

def inventory_service(headers):
    # 1. Extract context from incoming HTTP headers
    current_trace_id.set(headers.get("X-Trace-Id"))
    current_span_id.set(headers.get("X-Parent-Span-Id"))
    
    with Span("inventory_api_handler"):
        time.sleep(0.05) # Simulate work
        with Span("db_query_inventory"):
            time.sleep(0.15) # Slow DB query!
    
    return {"status": "in_stock"}

def order_service(headers):
    # 1. Extract context from incoming HTTP headers
    current_trace_id.set(headers.get("X-Trace-Id"))
    current_span_id.set(headers.get("X-Parent-Span-Id"))
    
    with Span("order_api_handler"):
        time.sleep(0.02)
        
        # 2. Inject context into OUTGOING HTTP headers
        outgoing_headers = {
            "X-Trace-Id": current_trace_id.get(),
            "X-Parent-Span-Id": current_span_id.get() # Pass MY span ID as the parent
        }
        print(f"[{current_trace_id.get()}] 🌐 HTTP GET /inventory (Headers: {outgoing_headers})")
        inventory_service(outgoing_headers)
        
    return {"status": "order_placed"}

def api_gateway():
    # 0. The Gateway is the entrypoint. It GENERATES the initial Trace ID.
    trace_id = str(uuid.uuid4())[:8]
    current_trace_id.set(trace_id)
    
    with Span("api_gateway_route"):
        outgoing_headers = {
            "X-Trace-Id": trace_id,
            "X-Parent-Span-Id": current_span_id.get()
        }
        order_service(outgoing_headers)


# ── Test Harness ──

if __name__ == "__main__":
    print("=== Simulating User Request ===")
    api_gateway()
    
    print("\n=== Trace Sent to Jaeger ===")
    print(json.dumps(trace_collector, indent=2))

Sample Output

=== Simulating User Request ===
[5b3e1a02] ▶ Start Span: api_gateway_route (ID: a1b2c3d4, Parent: None)
[5b3e1a02] ▶ Start Span: order_api_handler (ID: e5f6g7h8, Parent: a1b2c3d4)
[5b3e1a02] 🌐 HTTP GET /inventory (Headers: {'X-Trace-Id': '5b3e1a02', 'X-Parent-Span-Id': 'e5f6g7h8'})
[5b3e1a02] ▶ Start Span: inventory_api_handler (ID: i9j0k1l2, Parent: e5f6g7h8)
[5b3e1a02] ▶ Start Span: db_query_inventory (ID: m3n4o5p6, Parent: i9j0k1l2)
[5b3e1a02] ⏹ End Span  : db_query_inventory (151.2ms)
[5b3e1a02] ⏹ End Span  : inventory_api_handler (203.1ms)
[5b3e1a02] ⏹ End Span  : order_api_handler (225.4ms)
[5b3e1a02] ⏹ End Span  : api_gateway_route (225.8ms)

=== Trace Sent to Jaeger ===
[
  {
    "trace_id": "5b3e1a02",
    "span_id": "m3n4o5p6",
    "parent_id": "i9j0k1l2",
    "name": "db_query_inventory",
    "duration_ms": 151.2
  },
  // ... other spans
]

Notice how db_query_inventory knows its parent is inventory_api_handler, and all of them share the exact same Trace ID (5b3e1a02). Jaeger uses the parent IDs to draw the waterfall chart.

8. Complexity

9. Trade-offs

10. Production Evolution

11. Common Bugs

12. Interview Questions

1. What is the difference between Logging, Monitoring, and Tracing? Hint: The Three Pillars of Observability. Monitoring (Metrics) tells you IF something is wrong. Tracing tells you WHERE it is wrong (which service). Logging tells you WHY it is wrong (the specific error message).

2. How does a downstream service know it belongs to a trace? Hint: Context Propagation. The upstream service injects the Trace ID into the HTTP headers (e.g., W3C traceparent), and the downstream service extracts it.

3. What is Trace Sampling and why do we do it? Hint: Traces are massive. Storing 100% of traces for a high-traffic site is cost-prohibitive. We sample (e.g., keep 1% of successful traces, keep 100% of failed traces) to reduce storage costs while maintaining statistical visibility.

13. Used By (Downstream Blocks)

• 035 Service Mesh — Service Meshes (like Istio/Envoy) can automatically inject trace headers into network requests without the application developer doing anything.

14. Used In (Case Studies)

15. Related Blocks

16. Try It Yourself

Exercise 1: Tail-Based Sampling Simulator

Modify the __exit__ function. Instead of blindly appending to trace_collector, implement a simple Tail-Based sampler: Only append the span to the collector if duration_ms > 100. (Notice how this saves memory while still catching the slow DB query).

Exercise 2: Log Correlation

Modify the Span context manager to configure the standard Python logging module. Every time you call logging.info("Hello") inside a with Span(): block, it should automatically prepend [TraceID: 5b3e1a02] to the log output. This is how logs and traces are unified in production.

Website Metadata