Trace a slow request

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:

bun add @questpie/observability

Then add one key to your runtime config:

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:

docker run --rm -p 16686:16686 -p 4318:4318 jaegertracing/all-in-one:latest

OTLP_ENDPOINT=http://localhost:4318

Point the adapter at it and drop console:

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.

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:

-- 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.

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.

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.

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.

Before you ship it

Two changes, one line each.

Sample. Tracing every production request costs more than it tells you.

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.

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, every adapter option and how to write your own.
• Instrumented seams, every span QUESTPIE opens and what it deliberately leaves out.
• Monitoring, health probes and what to alert on.