A Backend Dev's Performance Tuning in Practice (4): Finding the Bottleneck with Slow Query

Foreword

On the road to performance tuning, aside from the app’s own performance issues, the database is another topic you can’t avoid. Nowadays, plenty of services can scale horizontally with K8s to boost performance, but the database usually stays a single monolithic instance — and under that setup, the pressure on the database is heavier than ever, which makes database optimization a major topic in its own right. Below, I’ll introduce two of the most common database performance-troubleshooting tools: Slow Query Log and the EXPLAIN syntax.

Slow Query Log

What is Slow Query? Simply put, it’s a SQL feature that logs any statement whose execution time crosses a certain threshold, making it easy for engineers to go back and review. When you want to check whether a particular query is running slow, the Slow Query Log is the first place to look.

You can check the current slow query setting with this command:

SHOW log_min_duration_statement;

The default value is -1, meaning the feature is disabled. In production, it’s recommended to turn it on. Here’s how to set it — say we want to flag any query that takes longer than 100 milliseconds:

ALTER SYSTEM SET log_min_duration_statement = 100;
SELECT pg_reload_conf();

Note that after setting up logging, you need to separately call pg_reload_conf() for the setting to take effect immediately. Also, this operation takes effect right away without needing to restart the DB.

Once that’s set up, we can try a query. For example, I ran the following against a ticket table where I’d pre-loaded over 1.5GB of fake data to simulate a slow query:

SELECT count(*) FROM ticket WHERE user_id = 200;

After running it, you can find the record in the PostgreSQL container log:

...
2026-07-13 02:49:11.796 UTC [302]: LOG:  duration: 245.075 ms  statement: SELECT count(*) FROM ticket WHERE user_id = 200;
2026-07-13 02:49:13.350 UTC [302]: LOG:  duration: 272.983 ms  statement: SELECT count(*) FROM ticket WHERE user_id = 200;
...

As you can see, this “look up a specific user’s tickets” query takes over 200 milliseconds — well past the 100ms threshold we set — which is exactly why we can find it recorded here.

So, we now know it’s slow. But where exactly is it slow? This is where we bring in our next tool: the EXPLAIN syntax.

EXPLAIN is a special piece of SQL syntax that analyzes a query and gives you detailed information about it. It doesn’t actually run the query first — it only performs an upfront analysis of it.

EXPLAIN SELECT count(*) FROM ticket WHERE user_id = 200;

Here’s the result:

Finalize Aggregate  (cost=179475.17..179475.18 rows=1 width=8)
  ->  Gather  (cost=179474.96..179475.17 rows=2 width=8)
        Workers Planned: 2
        ->  Partial Aggregate  (cost=178474.96..178474.97 rows=1 width=8)
              ->  Parallel Seq Scan on ticket  (cost=0.00..178455.61 rows=7737 width=0)
                    Filter: (user_id = 200)
JIT:
  Functions: 6
  Options: Inlining false, Optimization false, Expressions true, Deforming true

Seeing this table for the first time can feel a bit dizzying. Let’s pick out a few key fields:

Read from the inside out, bottom to top: the innermost, most deeply indented node (here, Parallel Seq Scan) executes first, and data flows upward layer by layer to the Aggregate that sums it all up.
cost=0.00..178455.61: this is the planner’s estimated cost — the first number is “the cost to return the first row,” the second is “the cost to run the entire node.” Note this is an abstract estimation unit, not milliseconds; the bigger the number, the more expensive the planner thinks it is.
rows=7737: the planner’s estimate of how many rows this node will output — an estimate, not necessarily accurate.
width=0: the estimated data width per row (in bytes). Since we’re only doing count(*) and don’t actually need any columns, it’s 0.

The most important part here is Parallel Seq Scan on ticket. A Seq Scan is a Full Table Scan — it means the database is going row by row through the entire ticket table looking for user_id = 200. This is usually the culprit behind poor performance — in this case, it’s because there’s no index on the user_id foreign key. But pure EXPLAIN is only an “estimate”; we can verify this by actually running it once with ANALYZE:

EXPLAIN (ANALYZE, BUFFERS) SELECT count(*) FROM ticket WHERE user_id = 200;

Result:

Finalize Aggregate  (cost=179475.17..179475.18 rows=1 width=8) (actual time=290.771..295.209 rows=1.00 loops=1)
  Buffers: shared hit=9916 read=120975
  ->  Gather  (cost=179474.96..179475.17 rows=2 width=8) (actual time=290.640..295.199 rows=3.00 loops=1)
        Workers Planned: 2
        Workers Launched: 2
        Buffers: shared hit=9916 read=120975
        ->  Partial Aggregate  (cost=178474.96..178474.97 rows=1 width=8) (actual time=271.163..271.164 rows=1.00 loops=3)
              Buffers: shared hit=9916 read=120975
              ->  Parallel Seq Scan on ticket  (cost=0.00..178455.61 rows=7737 width=0) (actual time=11.709..270.432 rows=5624.00 loops=3)
                    Filter: (user_id = 200)
                    Rows Removed by Filter: 3038511
                    Buffers: shared hit=9916 read=120975
Planning Time: 0.080 ms
JIT:
  Functions: 14
  Options: Inlining false, Optimization false, Expressions true, Deforming true
  Timing: Generation 2.172 ms (Deform 0.667 ms), Inlining 0.000 ms, Optimization 1.948 ms, Emission 28.265 ms, Total 32.385 ms
Execution Time: 295.586 ms

Adding ANALYZE makes PostgreSQL actually run the query once, so we now get actual time (actual elapsed time); adding BUFFERS on top of that tells us whether the data came from memory or disk. Two numbers in this table explain “where it’s slow” better than anything else:

Rows Removed by Filter: 3038511: this is the single most damning number in the whole report. It means the database scanned through and threw away 3 million rows, just to keep the few thousand rows we actually wanted. This is the pain of a Full Table Scan — most of the work is wasted work.
Buffers: shared hit=9916 read=120975: hit means it was served from memory (fast), read means it actually had to fetch blocks from disk (slow). Here, read clocks in at a whopping 120,000 blocks, meaning a huge amount of data had to be pulled up from disk. Keep this number in mind — the contrast after we add an index is going to be dramatic.
actual time=290.771..295.209 / Execution Time: 295.586 ms: the bottom-line summary — this query actually took about 300 milliseconds to run.

That’s a latency of about 300 milliseconds — very high. At this point, we can optimize the query speed by adding an index:

CREATE INDEX CONCURRENTLY idx_ticket_user_id ON ticket(user_id);

Running ANALYZE again gives us this:

Aggregate  (cost=435.81..435.82 rows=1 width=8) (actual time=1.882..1.883 rows=1.00 loops=1)
  Buffers: shared hit=22
  ->  Index Only Scan using idx_ticket_user_id on ticket  (cost=0.43..389.39 rows=18569 width=0) (actual time=0.019..1.036 rows=16872.00 loops=1)
        Index Cond: (user_id = 200)
        Heap Fetches: 0
        Index Searches: 1
        Buffers: shared hit=22
Planning:
  Buffers: shared hit=12 read=1
Planning Time: 0.374 ms
Execution Time: 1.935 ms

Putting the key numbers from both reports side by side, the impact becomes crystal clear:

Metric	Before Index	After Index
Scan method	Parallel Seq Scan (full table scan)	Index Only Scan (via index)
Buffers read (disk reads)	120975	0 (`shared hit=22`)
Rows Removed by Filter	3038511	0
Execution Time	295.586 ms	1.935 ms

Execution time dropped from about 300 milliseconds down to 1.9 milliseconds — roughly 150x faster. Even more importantly, it no longer scans the whole table or has to fetch 120,000 blocks off disk — it finds the answer directly through the index. This is exactly why knowing how to read EXPLAIN matters so much: it tells you directly “where it’s slow,” so you know exactly what to treat.

And that’s a simple application of Slow Query + EXPLAIN put together. That’s it for this article.