How to Trace Slow Requests With OpenTelemetry in Python

Why you cannot see where the time goes

A handler like /work calls three functions in sequence - load_user, fetch_quote, and save_log. From the outside the request just takes 300ms. Without instrumentation there is no signal about which of the three is the bottleneck, so you end up adding print(time.time()) lines or guessing. Distributed tracing solves this by recording each unit of work as a named span with a start and end time, so the trace tree tells you exactly which call is slow.

This works the same whether you are on Flask or FastAPI - the OpenTelemetry API for manual spans is identical. Auto-instrumentation covers the inbound request; manual spans name the business operations the auto-instrumentation cannot.

Wire up a TracerProvider

A TracerProvider produces tracers, and a span processor decides where finished spans go. For local inspection, feed spans into an InMemorySpanExporter so you can read them back from an endpoint - no external collector needed:

from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import SimpleSpanProcessor
from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter

exporter = InMemorySpanExporter()

provider = TracerProvider()
provider.add_span_processor(SimpleSpanProcessor(exporter))
trace.set_tracer_provider(provider)

tracer = trace.get_tracer(__name__)

Do this once at module level, before the app starts handling requests. SimpleSpanProcessor exports each span synchronously as it finishes - perfect for a demo or a test; production uses BatchSpanProcessor instead.

Wrap each operation in a named span

Now wrap each internal call in tracer.start_as_current_span("name"). The context manager records the wall-clock duration and closes the span when the block exits:

def load_user():
    with tracer.start_as_current_span("load_user"):
        time.sleep(0.05)
        return {"id": 1, "name": "alice"}


def fetch_quote():
    with tracer.start_as_current_span("fetch_quote"):
        time.sleep(0.20)  # the slow one
        return {"quote": "the only easy day was yesterday"}


def save_log(payload):
    with tracer.start_as_current_span("save_log"):
        time.sleep(0.05)
        return True

Each with block becomes one span. Because they run inside the same request, they share a trace, and the tree shows all three side by side under the handler.

Read the durations back

Expose the captured spans so you can see the timings. The finished spans carry start_time and end_time in nanoseconds:

@app.route("/traces")
def traces():
    spans = exporter.get_finished_spans()
    return jsonify([{
        "name": s.name,
        "duration_ms": (s.end_time - s.start_time) / 1_000_000,
    } for s in spans])

Hit the endpoint, then read the traces:

curl http://localhost:5001/work
curl http://localhost:5001/traces | python3 -m json.tool

You will see three spans - and fetch_quote at ~200ms is four times slower than the other two. That is the number that turns "it feels slow" into a concrete target for caching or a fix.

Going to production

In production you do not read spans from memory. Swap the InMemorySpanExporter for an OTLP exporter pointing at a collector (otel-collector, Tempo, Honeycomb, Datadog) and use a BatchSpanProcessor. Add auto-instrumentation packages (opentelemetry-instrumentation-flask, -fastapi, -requests, -psycopg2) to get HTTP and DB spans for free - the manual spans you added stay for the business operations only your code understands.