Slow queries: from symptom to cause, without guessing

When a Filetable page is slow, everything points at the database. Often wrongly. A slow page can come from a badly written query, a query repeated too often, or a database that has nothing to do with it. The difference does not show when reading the code: it has to be measured.

The context: Postgres, and what it does not say

Filetable stores everything in PostgreSQL: customers' tables, their relations, their filters. It is a deliberate choice: a solid relational database, transactions, indexes, and JSON columns where flexibility is needed.

Postgres can tell which queries cost it the most. But it does not know which page issued them, nor how long the user really waited: between the application and the database sit a connection pool, a network and a shared CPU. So you measure on both sides, and tie them together: every slow query keeps a trace of the page that issued it, and every slow page leads to its queries, through distributed tracing with OpenTelemetry, the open standard for observability.

Measure

The querycarries the name of the page that issued it

The timeraround every call, waiting included

A bufferwritten in batches, off the path

The logthe query's shape, never its values

Then read: from cost to cause

1The cost per pagesorted by total time
2Its slow querieshow many, median, maximum
3The traceevery call on a timeline

Every query is timed around the call to the database, waiting included. The slowest are kept with the page that issued them, then written in batches, off the user's path.

The challenge. Measure every query without slowing any of them down. Three rules: never on the user's path, never the parameter values (they are customer data), and never its own write, or the first slow measurement ends up measuring itself.

Sort by the bill, not the record

p95, the time under which 95% of calls fall, names the slowest page, not the most expensive one. An export almost never called can show thirty seconds and bother nobody; a two-second read called on every click costs hours of waiting a day. So we sort by total time: number of calls × mean duration.

Read the shape, not the values

Once the page is found, its slow queries almost always have one of these three shapes, and each one points to a different cause.

Read the shape, not the values

many executions, all alikeA cheap query run too many times: an N+1

few executions, one very slowOne expensive query: look at its plan

everything around the same timeNot the database: the pool or the CPU

Each dot is one captured slow execution, on a log axis. Schematic: what matters is the shape of the cloud, not the exact value.

The trace confirms it

The trace of an HTTP request shows every database call on a timeline. You count rather than interpret:

Many calls side by side

→ N+1: one batched query for all the items.

One long call

→ Heavy query: read its execution plan, the index, the statistics.

Schematic. On the left, the same query per item, fired in parallel, queuing for a connection. On the right, a single query that takes all the time.

Four real cases

None of them showed when reading the code. All of them showed within minutes in the measurements.

× 40the same small query within one page
N+1
Cause
A loop: one query per item, all fired at once.
Fix
One batched query. The number of calls no longer depends on the number of items.
> 10 sto delete a single row
cascade
Cause
Cascading deletes, invisible in the plan, scanned whole tables for lack of an index.
Fix
An index on every foreign key, and a query that lists the ones missing it.
× 400more time compiling the query than running it
planner
Cause
Postgres' JIT compiler kicks in on an estimate that is far too high, and cannot be cancelled.
Fix
JIT turned off: at our volumes, it slowed down even large aggregates.
× 4000between the time the app sees and the time Postgres sees
resources
Cause
Waiting for a free connection, and a CPU throttled by its limit.
Fix
Cap parallel queries, and watch the container's throttling, not the machine's CPU.

Four cases measured in development, values rounded. None of them showed when reading the code.

What I take from it

Shape before value. The number of calls and their spread already tell you where to look.
Ask Postgres what it thinks. When the app measures 400 ms and the database 0.1 ms, the problem is not in the query.
A comment defending a loop is not evidence. A batched, measured query is.