{"course":{"slug":"cloud-and-shipping","title":"Shipping It","url":"https://addaly.com/learn/cloud-and-shipping","level":"intermediate","track":"build"},"lesson":{"slug":"tracing-one-slow-request","title":"Finding the slow bit","url":"https://addaly.com/learn/cloud-and-shipping/tracing-one-slow-request","position":28,"of":74,"minutes":10,"answer":"Slowness is nearly always waiting rather than computing, and a trace or a few timed log lines will show you what the request was waiting for.","keyIdea":"Slowness is nearly always waiting rather than computing, and a trace or a few timed log lines will show you what the request was waiting for."},"body":{"format":"markdown","text":"## From a request ID to a shape\n\nYou 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.\n\n```\nGET /orders                                     840ms\n├─ auth.verify                                    4ms\n├─ db.query orders                               31ms\n├─ loop over 40 orders\n│  ├─ db.query customer                           3ms\n│  ├─ db.query customer                           3ms\n│  └─ ... 38 more                               114ms\n└─ http POST payments.example.com                610ms\n```\n\nYou 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.\n\n## The three culprits, in order of frequency\n\n**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.\n\n**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.\n\n**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.\n\n## You can do this without a tracing backend\n\nTracing tools are good and you do not need one to start. Log a duration at each boundary with the request ID:\n\n```\nreq=a7f3 span=db.orders ms=31\nreq=a7f3 span=http.payments ms=610\nreq=a7f3 span=total ms=840\n```\n\nSort by `ms`. That is 80% of a trace for an afternoon's work, and it works with the log tooling you already have.\n\n## The database's own answers\n\nTwo Postgres features do most of the work:\n\n`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.\n\n`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.\n\n## Sampling, when there is too much\n\nTracing 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.\n\n## The free path\n\n**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.\n\nStart with timed log lines. Move to real tracing when you can no longer answer \"where did the time go\" in one pass."},"check":{"question":"A report endpoint takes 4 seconds. The database is at 12% CPU, and each of the queries the endpoint runs takes under 10ms when you run it by hand. Which explanation fits best?","options":[{"text":"The queries are slow only when run together, because they contend for the same table lock","correct":false,"tempting":"Possible under write-heavy load, but the database is nearly idle and read queries do not block each other in Postgres."},{"text":"The report result is too large to serialise quickly, so the time is spent building JSON","correct":false,"tempting":"Worth measuring, and occasionally true, but this would show as CPU on the app server rather than as a request that is mostly waiting."},{"text":"The query planner is choosing a bad plan under production data volumes","correct":false,"tempting":"A real and common cause of slow endpoints, but it contradicts the given fact that each query runs in under 10ms against the same data."},{"text":"The endpoint runs many small queries and spends most of its time either repeating them in a loop or waiting to acquire a connection, neither of which shows up when you time one query by hand","correct":true}]},"prev":{"slug":"slos-and-error-budgets","title":"Deciding how reliable it has to be","url":"https://addaly.com/learn/cloud-and-shipping/slos-and-error-budgets"},"next":{"slug":"the-bill","title":"The bill, and the traffic that runs it up","url":"https://addaly.com/learn/cloud-and-shipping/the-bill"},"authorship":"Founder and series editor: Dr Mustafa Mun. Written by AI models to a written standard. Exam keys checked blind by a second model: 3,665 of 3,666 agreed. Academic review invited.","review":{"status":"Draft, open for academic review"},"cite":"Addaly (2026) 'Finding the slow bit', in Shipping It. Edited by M. Mun. Addaly. Available at: https://addaly.com/learn/cloud-and-shipping/tracing-one-slow-request (Accessed: 13 October 2026).","licence":{"name":"CC BY-NC-SA 4.0","url":"https://creativecommons.org/licenses/by-nc-sa/4.0/"},"reader":{"schema":1,"title":"Finding the slow bit","courseTitle":"Shipping It","module":{"index":3,"slug":"knowing-what-it-is-doing","title":"Knowing what it is doing"},"answer":null,"keyIdea":"Slowness is nearly always waiting rather than computing, and a trace or a few timed log lines will show you what the request was waiting for.","hero":{"kind":"plate","image":null,"alt":null,"caption":null},"blocks":[{"t":"h2","id":"from-a-request-id-to-a-shape","runs":[{"text":"From a request ID to a shape"}]},{"t":"p","runs":[{"text":"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 "},{"text":"spans","b":true},{"text":", each with a start time and a duration, all sharing one trace ID."}]},{"t":"code","lang":"","label":"Text","text":"GET /orders                                     840ms\n├─ auth.verify                                    4ms\n├─ db.query orders                               31ms\n├─ loop over 40 orders\n│  ├─ db.query customer                           3ms\n│  ├─ db.query customer                           3ms\n│  └─ ... 38 more                               114ms\n└─ http POST payments.example.com                610ms"},{"t":"p","runs":[{"text":"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."}]},{"t":"h2","id":"the-three-culprits-in-order-of-frequency","runs":[{"text":"The three culprits, in order of frequency"}]},{"t":"p","runs":[{"text":"The N+1 query.","b":true},{"text":" 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."}]},{"t":"p","runs":[{"text":"A third-party call with no timeout.","b":true},{"text":" 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."}]},{"t":"p","runs":[{"text":"Waiting for a resource.","b":true},{"text":" 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 "},{"text":"acquire","i":true},{"text":" a connection, this time is invisible and you will chase the wrong thing for a day."}]},{"t":"h2","id":"you-can-do-this-without-a-tracing-backend","runs":[{"text":"You can do this without a tracing backend"}]},{"t":"p","runs":[{"text":"Tracing tools are good and you do not need one to start. Log a duration at each boundary with the request ID:"}]},{"t":"code","lang":"","label":"Text","text":"req=a7f3 span=db.orders ms=31\nreq=a7f3 span=http.payments ms=610\nreq=a7f3 span=total ms=840"},{"t":"p","runs":[{"text":"Sort by "},{"text":"ms","code":true},{"text":". That is 80% of a trace for an afternoon’s work, and it works with the log tooling you already have."}]},{"t":"h2","id":"the-database-s-own-answers","runs":[{"text":"The database’s own answers"}]},{"t":"p","runs":[{"text":"Two Postgres features do most of the work:"}]},{"t":"p","runs":[{"text":"EXPLAIN (ANALYZE, BUFFERS)","code":true},{"text":" 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."}]},{"t":"p","runs":[{"text":"pg_stat_statements","code":true},{"text":" 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."}]},{"t":"h2","id":"sampling-when-there-is-too-much","runs":[{"text":"Sampling, when there is too much"}]},{"t":"p","runs":[{"text":"Tracing every request at high traffic is expensive to store. The standard answer is "},{"text":"tail sampling","b":true},{"text":": 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."}]},{"t":"h2","id":"the-free-path","runs":[{"text":"The free path"}],"role":"free"},{"t":"p","runs":[{"text":"OpenTelemetry","b":true},{"text":" is the vendor-neutral standard for producing traces; instrument once and you can change backend later. For the backend: "},{"text":"Jaeger","b":true},{"text":" and "},{"text":"Grafana Tempo","b":true},{"text":" are free and self-hostable; "},{"text":"SigNoz","b":true},{"text":" 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."}]},{"t":"p","runs":[{"text":"Start with timed log lines. Move to real tracing when you can no longer answer “where did the time go” in one pass."}]}],"check":{"question":[{"text":"A report endpoint takes 4 seconds. The database is at 12% CPU, and each of the queries the endpoint runs takes under 10ms when you run it by hand. Which explanation fits best?"}],"options":[{"text":[{"text":"The queries are slow only when run together, because they contend for the same table lock"}],"correct":false,"tempting":[{"text":"Possible under write-heavy load, but the database is nearly idle and read queries do not block each other in Postgres."}]},{"text":[{"text":"The report result is too large to serialise quickly, so the time is spent building JSON"}],"correct":false,"tempting":[{"text":"Worth measuring, and occasionally true, but this would show as CPU on the app server rather than as a request that is mostly waiting."}]},{"text":[{"text":"The query planner is choosing a bad plan under production data volumes"}],"correct":false,"tempting":[{"text":"A real and common cause of slow endpoints, but it contradicts the given fact that each query runs in under 10ms against the same data."}]},{"text":[{"text":"The endpoint runs many small queries and spends most of its time either repeating them in a loop or waiting to acquire a connection, neither of which shows up when you time one query by hand"}],"correct":true,"tempting":null}],"order":[2,3,0,1],"why":null},"prev":{"slug":"slos-and-error-budgets","title":"Deciding how reliable it has to be","minutes":10},"next":{"slug":"the-bill","title":"The bill, and the traffic that runs it up","minutes":9}}}