# Trace a slow request (/docs/guides/debug-a-slow-request)
---
title: Trace a slow request
description: Wire OpenTelemetry into a QUESTPIE app, run a collector locally, and read the waterfall down to the SQL statement that was actually slow.
kind: guide
package: "@questpie/observability"
---
Someone says the orders page is slow. The usual next step is a guess. Do this
instead. You end up holding the exact SQL statement to run `EXPLAIN` on.
## Turn it on
Install the adapter:
```bash
bun add @questpie/observability
```
Then add one key to your runtime config:
```ts title="src/questpie/server/questpie.config.ts"
import { otelObservability } from "@questpie/observability";
import { runtimeConfig } from "questpie/app";
export default runtimeConfig({
// ...db, storage, email
observability: {
adapter: otelObservability({
serviceName: "my-app",
environment: process.env.NODE_ENV,
console: true,
}),
},
});
```
That is enough to see something. `console: true` prints each span to stdout as
it ends, unbatched. Start the app with `bun run dev` and hit a route.
No `otlpEndpoint` is set here, so nothing is exported over the network. Spans
still open and still nest. That is why the adapter is safe to leave wired in
development.
## Run a collector
Stdout is fine for one span and useless for thirty. You want a waterfall.
Any OTLP/HTTP collector works. Jaeger's all-in-one image is the shortest path:
```bash
docker run --rm -p 16686:16686 -p 4318:4318 jaegertracing/all-in-one:latest
```
```bash title=".env"
OTLP_ENDPOINT=http://localhost:4318
```
Point the adapter at it and drop `console`:
```ts
otelObservability({
serviceName: "my-app",
environment: process.env.NODE_ENV,
otlpEndpoint: process.env.OTLP_ENDPOINT,
});
```
That is a base URL. Traces post to `/v1/traces` under it, metrics to
`/v1/metrics`, logs to `/v1/logs`. Restart the app, make the slow request, then
open `http://localhost:16686` and pick your service.
## Read the waterfall
A `GET /api/orders` comes back looking roughly like this:
```
GET /api/orders 142ms server
└─ collection.find 138ms internal db.collection.name=orders
├─ db.select 4ms client db.sql.table=orders
└─ db.select 131ms client db.sql.table=order_items
```
Read it top down. The root span is the request. The `internal` span is one call
to `app.collections.orders.find()`. The `client` spans are the statements that
call ran.
The last line is the answer. The route is not slow. The collection call is not
slow. One query against `order_items` is.
Child spans do not merely share a trace id. Each one names its parent. So a
statement inside `db.transaction()` appears under the transaction span. On
writes that is usually where the surprise lives.
## Take the statement to EXPLAIN
Open the slow `db.select` span. `db.statement` carries the SQL text QUESTPIE
sent.
The parameters are not on it. A tracing backend is searchable and widely
readable inside a company. Parameters are user data. So put your own values in
and run it yourself:
```sql
-- db.statement, with real values in place of $1
EXPLAIN ANALYZE SELECT * FROM "order_items" WHERE "order_id" = 42;
```
Now you have a query and a number instead of a guess. The usual fix is an index
you never declared. See [Indexes](/docs/schema/collections#indexes).
## Time what QUESTPIE cannot see
Seven seams open spans: HTTP requests, collection CRUD, database queries,
transactions, job runs, KV calls and search queries.
Your route is already one of them. The request span is named after the matched
pattern, `GET /orders`, and carries it as `http.route`. Your handler runs inside
it, so its total time is on the waterfall already. A second span around the same
handler would start and end within a millisecond of the request span, which is
why there is not one.
What the waterfall cannot show is the shape inside that handler. A payment call
and an image pipeline both sit in the request span with no line of their own.
Only you know where the boundaries worth naming are.
```ts title="src/questpie/server/routes/orders.get.ts"
import { route } from "questpie/services";
export default route()
.get()
.handler(async ({ observability, collections }) => {
const orders = await collections.orders.find({ limit: 50 });
const rates = await observability.span(
"rates.fetch",
() => fetch("https://rates.example.com/latest").then((r) => r.json()),
{ kind: "client", attributes: { "rates.provider": "example" } },
);
return { orders: orders.docs, rates };
});
```
`span(name, fn, options)` nests under whatever span is active, so this lands in
the same waterfall with no wiring. It waits for the promise to settle before
ending. It records the error and rethrows rather than swallowing. It works with
no adapter configured too, at the cost of one function call.
## Join the logs to the trace
Every line logged inside that request already carries the span's ids. `logger`
sits on the same handler context, and nothing gets threaded through.
```ts
logger.info("orders listed", { count: orders.docs.length });
```
The record picks up `trace_id` and `span_id` in snake case. Those are the keys a
log backend joins traces on. Search that trace id and you get exactly the lines
from this request. That includes the ones written inside the slow query's span.
`trace_id` is the span's. That is the one your backend knows. The camelCase
`traceId` beside it is QUESTPIE's own. It reads `x-trace-id`, then the inbound
`traceparent`, then falls back to the request id. Join on `trace_id`.
## Before you ship it
Two changes, one line each.
**Sample.** Tracing every production request costs more than it tells you.
```ts
otelObservability({ serviceName: "my-app", samplingRatio: 0.1 });
```
That keeps a tenth of traces whole. The sampler is parent-based, so a request
that arrived already sampled stays sampled whatever the ratio says. A bare ratio
sampler would cut traces off at your service. A trace with a hole in it reads as
a bug in the caller.
**Flush.** Spans are batched. A process that exits without flushing loses the
last batch. That batch is the interesting one more often than not.
```ts
process.on("SIGTERM", async () => {
await app.destroy();
process.exit(0);
});
```
`app.destroy()` tears services down in reverse order. The database, queue,
search and realtime have all stopped emitting by the time observability flushes.
Use `await app.observability.shutdown()` if you are tearing the rest down
yourself.
## Related
- [Observability](/docs/infrastructure/observability), every adapter option and how to write your own.
- [Instrumented seams](/docs/infrastructure/observability/seams), every span QUESTPIE opens and what it deliberately leaves out.
- [Monitoring](/docs/ship/monitoring), health probes and what to alert on.