Finding the slow bit

From a request ID to a shape

You already give every request an ID and log it everywhere. A trace is the next step: instead of scattered lines, you get a tree of spans, each with a start time and a duration, all sharing one trace ID.

GET /orders                                     840ms
├─ auth.verify                                    4ms
├─ db.query orders                               31ms
├─ loop over 40 orders
│  ├─ db.query customer                           3ms
│  ├─ db.query customer                           3ms
│  └─ ... 38 more                               114ms
└─ http POST payments.example.com                610ms

You do not have to guess. The picture says the request spent 610ms waiting for a third party and 120ms doing a query it ran forty times.

The three culprits, in order of frequency

The N+1 query. One query to fetch a list, then one query per item. Forty items at 3ms is 120ms of latency created by a loop that reads perfectly well in code review. It is invisible until you count queries per request, and it scales with your data, so it appears three months after the code is written.

A third-party call with no timeout. Their p99 becomes your p99. Every outbound HTTP call needs an explicit timeout, and here is the subtlety: a 30-second timeout on a call inside a request that itself times out at 10 seconds is not a timeout. Set it below your own budget. Then decide what to do when it fires: a degraded page is usually better than an error page.

Waiting for a resource. The request spends 800ms not working at all: waiting for a connection from the pool, waiting for a lock, waiting behind a queue. This is the one that looks like “the database is slow” when the database is idle. If you instrument only the query and not the wait to acquire a connection, this time is invisible and you will chase the wrong thing for a day.

You can do this without a tracing backend

Tracing tools are good and you do not need one to start. Log a duration at each boundary with the request ID:

req=a7f3 span=db.orders ms=31
req=a7f3 span=http.payments ms=610
req=a7f3 span=total ms=840

Sort by ms. That is 80% of a trace for an afternoon’s work, and it works with the log tooling you already have.

The database’s own answers

Two Postgres features do most of the work:

EXPLAIN (ANALYZE, BUFFERS) runs the query and shows you the plan with real timings and real row counts. The thing to look for is a large gap between estimated and actual rows: that means the planner chose a strategy based on a wrong guess, which is how a query that was fast last month is slow now.

pg_stat_statements ranks queries by total time across all executions. This is where the counter-intuitive finding lives: the query taking 3ms but running 40,000 times an hour costs far more than the 900ms report somebody complained about. Optimising by total time rather than by worst single time is usually the higher-value order.

Sampling, when there is too much

Tracing every request at high traffic is expensive to store. The standard answer is tail sampling: keep 100% of traces that errored or exceeded a latency threshold, and 1% of the rest. You keep every interesting trace and pay for almost none of the boring ones.

The free path

OpenTelemetry is the vendor-neutral standard for producing traces; instrument once and you can change backend later. For the backend: Jaeger and Grafana Tempo are free and self-hostable; SigNoz bundles traces, metrics and logs in one open-source install. Honeycomb, Datadog and New Relic are the paid options, and Honeycomb in particular is very good at the high-cardinality questions (“which requests are slow, and what do they have in common?”) that metrics cannot answer.

Start with timed log lines. Move to real tracing when you can no longer answer “where did the time go” in one pass.