A slow page in our CRM: measure first, then (maybe) optimise

There was a page in our CRM that kept you waiting every time you opened it. Not long enough to stop work, but long enough to be noticed every single time. In a system people use all day, a page that hesitates soon becomes the irritation everyone talks about.

Suspicion fell on a query straight away. Inside it sat a correlated subquery, an exists that, for every row, went off to check something in another part of the data. We already had the rewrite worked out in our heads.

We didn't rewrite it. We measured first, and the measurement told us we were about to fix the wrong thing.

The perfect culprit

Correlated subqueries have a bad reputation, and not an entirely undeserved one: on paper they describe work that has to be repeated row by row, and anyone who has read a bit of advice on database performance learns to eye them warily. When a page is slow and you find one in the code, the case seems to close itself.

That is precisely the problem. A suspicious-looking query is a convenient explanation, because it hands us something concrete to do. But "it looks slow" is not a measurement. It's an impression, and impressions about performance are wrong more often than we like to admit.

What we actually measured

The method we use now is simple, and we apply it before touching a single line of code.

First: we log every query the pool runs while the page loads. Not just the suspect: all of them. A page often makes more requests to the database than we remember, and the full list is useful information in itself.

Second: we replay them one by one with explain analyze. Unlike plain explain, which only shows the expected plan, explain analyze actually runs the query and returns the plan with the real timing of each step. It's the difference between asking Postgres what it intends to do and watching it do it.

The result caught us off guard. The query in the dock, the one with the exists, was resolved by Postgres in a single scan. No row-by-row repetition: the planner had found an efficient route on its own. The rewrite we had in mind would have gained nothing.

So where were the nearly thousand milliseconds of waiting coming from?

The database that was asleep

They came from somewhere we hadn't considered: our database is serverless, and after a period of inactivity it goes to sleep. The slowness we were seeing was it waking up. Whoever opened the page at that moment paid the wait for the database to start again, and blamed it on the first thing that came to mind.

It's worth pausing on what would have happened had we followed our instinct. We would have spent time rewriting a query that worked perfectly well, at the risk of introducing a bug into a part of the system that had no problems. And worse still: we might have tested the new version while the database was already awake, seen the page respond quickly and convinced ourselves we'd fixed it. A false success is more dangerous than a failure, because it ends the search.

It's the mistake that taught us the most, and that's exactly why we're telling it.

The second question: is the time in the database or outside it?

Slowness doesn't always live in the database, and the method helps us work that out too. The comparison we make is between two numbers: the total page load time and the time spent in the database, that is, the sum of the queries we logged.

If the two are close, the work to be done is in the queries, and explain analyze tells us where. If, on the other hand, the total time is much higher than the database time, the bottleneck is elsewhere: almost always synchronous JavaScript blocking the thread. A heavy calculation, a loop over too much data, a transformation done all in one go: while that code is running, nothing else moves.

To find it we use a very home-made trick: we put a stopwatch after every await. Each time the code waits for something, we note how much time has passed. The intervals that contain a genuine wait explain themselves; the one that grows when there's nothing to wait for points to the piece of code hogging the thread. It isn't elegant, but it takes you straight to the point, and once the culprit is found the stopwatches come out.

The method, in short

This is the order we follow every time a page feels slow:

1. Log every query the pool runs during loading.
2. Replay them with explain analyze to see the real timings, not the imagined ones.
3. Compare the page's total time with the time spent in the database.
4. If the gap is large, hunt for synchronous code with a stopwatch after every await.
5. Only then decide what to optimise.

None of these steps needs special tools. It just takes the patience not to rush straight to the solution.

What we take away

In the end, the lesson fits on one line: you optimise what you have measured, not what looks slow.

Put like that it sounds obvious, but in practice it goes against instinct. When something is slow we want to get our hands on it, and the temptation to go straight for the most likely suspect is strong, especially when the suspect looks like a textbook culprit. In our case the textbook culprit was innocent, and the real one wasn't even in code we had written.

Since then, whenever one of us says "this page is slow, I reckon it's that query", the answer is always the same: fine, let's measure it.