Databases Under Load: Indexes, Slow Queries and the First Bottleneck

The query ran in three milliseconds, so it shipped at ten to five on a Friday.

Marlow Books is a four person online bookshop that exists only in this course, and the founder had tested that query on a laptop holding a dump of two thousand titles. The real catalogue has 1.2 million. On a Friday in May, a month after the shop sold forty copies of a novel it had twelve of, they built the page the two buyers had been asking for since the distributor mess: every title from one publisher, newest first, twenty to a page. A link to it went on every book page, reading "more from this publisher".

They did test it in production before leaving. It took 3.1 seconds. They hit refresh, got 290 milliseconds, decided the first had been a cold start, and went home.

Over the weekend the search engine crawler from lesson 008, the one walking about forty distinct ISBNs a second that never went away, re-read the book pages and found the new link on every one of them. The page had paging, because a publisher can have sixty thousand titles, and two sort orders, because the buyers wanted date and title. A catalogue of 1.2 million in pages of twenty is sixty thousand pages, times two sorts is a hundred and twenty thousand URLs the robot had never seen. Fetching URLs it has never seen is a crawler's entire job.

It started on them at four on Sunday morning, and it was still working through the queue when the founder woke up on Monday.

Sunday was a bad day at Marlow Books and nobody said a word, because customers do not email you when a site is slow. They leave. Orders came in about a fifth below a normal Sunday, which the founder cannot prove was the cause and neither can I. Every request returned 200. No alert fired, and the founder spent the afternoon with their family.

At 09:14 on Monday a buyer messaged to say the new page was broken, which is what a page looks like when it takes four seconds. Postgres on box A, Marlow's database machine since lesson 005, was at 76% CPU across sixteen cores, with 40 requests a second arriving: the traffic of a quiet Tuesday. Lesson 001 named that shape, the hockey stick at eighty percent. Load does nothing, nothing, nothing, and then everything at once.

Twelve of those sixteen cores belonged to the crawler, which had not raised its rate by a single request. Forty a second is what it had been doing since March, when it cost the shop eight points of cache hit rate for a week and nothing worse. What changed was the price of one request: two milliseconds for a cached book page, 290 for the new one. And a robot's rate is not a promise to slow down. This one holds about a dozen fetches open at once, and a dozen at 290 milliseconds each is forty a second by itself, so the rate never moved. Lesson 006 called that open loop, in the balancer that keeps handing a sick box its share.

Here is the query, and it is the most ordinary one in the world.

SELECT isbn, title, author, price
FROM books
WHERE publisher_id = 41
ORDER BY published_at DESC
LIMIT 20;

There was an index on publisher_id, put there on purpose, on the grounds that you index the thing you filter on. The index was used. EXPLAIN said so.

It took 3.1 seconds anyway, and at 23:10 that Monday one extra index took it to 0.38 milliseconds. Same rows, same disk, same server, same twenty results.

Rows examined against rows returned

Every query has two row counts, and the gap between them is the whole subject.

Rows returned is what the client gets: twenty, because of the LIMIT. Rows examined is what the database had to touch to be sure those were the right twenty. Publisher 41 is Marlow's largest, about sixty thousand titles, five percent of the catalogue. To find the twenty newest, the database read all sixty thousand, sorted them by date, and threw away 59,920.

Three thousand rows examined for every row returned.

That ratio is the first thing I ask for when somebody says a query is slow, before I look at the SQL. It says which kind of problem you have. A query examining twenty rows to return twenty is doing the least work it can, and if it's still slow the cause is elsewhere: the network, a lock, a hundred copies running at once. Sixty thousand to return twenty is nearly all waste, and no faster disk fixes a ratio.

Now price the work. Postgres stores rows in 8 kilobyte pages and reads a whole page even when it wants one row. Marlow's books row is about two hundred bytes for the columns this query touches, because Postgres moves oversized values like the description out of line, which is why a table full of text can still have narrow pages. Two hundred bytes into eight kilobytes is about forty rows a page, so 1.2 million rows occupy thirty thousand pages, 240 megabytes.

Sixty thousand rows scattered across thirty thousand pages. How many pages is that?

Not sixty thousand, because pages get revisited, and not thirty thousand either. Scatter sixty thousand darts over thirty thousand boxes and the number of boxes with at least one dart is thirty thousand times one minus one over e squared: 25,900, eighty six percent of the table.

The index found the rows. It just found them one at a time, in publisher order, which has nothing to do with the order they sit on disk.

Ask the database what it plans to do

EXPLAIN shows the plan. EXPLAIN ANALYZE runs the query and puts real numbers beside the estimates, which is the only version worth reading, and BUFFERS adds how many pages it found in memory against how many it fetched. Monday morning's, trimmed to what matters:

Limit  (actual time=3118.9..3121.4 rows=20)
  ->  Sort  (actual time=3118.9..3120.2 rows=20)
        Sort Key: published_at DESC
        Sort Method: top-N heapsort  Memory: 29kB
        ->  Index Scan using books_publisher_idx on books
              (actual time=0.4..2901.7 rows=59940 loops=1)
              Index Cond: (publisher_id = 41)
              Buffers: shared hit=412 read=25718
 Execution Time: 3121.6 ms

Read it from the inside out, the order it happens in.

The index scan at the bottom walked the index for publisher_id = 41 and fetched every matching row: rows=59940. read=25718 is the pages it had to go and get, within a percent of the 25,900 the dart arithmetic predicted. Twenty six thousand random page reads at lesson 002's hundred microseconds for an SSD is 2.6 seconds, and the measured 2.9 is that plus the index walk and the row assembly.

Above it, a Sort node. Sixty thousand rows sorted by published_at to pick twenty, and Postgres is not stupid about it: top-N heapsort means it kept only the best twenty in a 29 kilobyte heap instead of sorting all sixty thousand, so the sort itself is nearly free. The sort is not the cost. The sort is the evidence. A Sort above a scan means the rows did not arrive in the order you asked for, so all of them had to be fetched before the first could be returned.

Which is the expensive part. LIMIT 20 cannot help when the plan has a sort in it, because you cannot know which twenty are newest until you have seen all sixty thousand.

The index was there. The sort was the problem.

An index is a sorted copy of one or more columns, held as a tree of the same 8 kilobyte pages. Over Marlow's 1.2 million titles it is three levels. The root page holds a few hundred boundary values pointing at the level below, that level does the same, and the bottom level holds the entries themselves with a pointer to each row. Finding any value is three page reads, and that count barely moves with size: four levels already cover tens of billions of rows. Which is 002's promise paid, fewer rungs of the ladder and fewer times.

What a tree cannot do is change the order it was built in. An index on one column gives you rows in that column's order. Marlow's index on publisher_id hands out publisher 41's sixty thousand titles in publisher order, then physical order. Not by date. The date order has to be built afterwards, from all of them.

A composite index, one built on more than one column, is a different shape. (publisher_id, published_at) sorts by publisher first and then, within each publisher, by date. Publisher 41's titles sit together in the index, already in date order, so the database walks to the start of that publisher's block, reads backwards for twenty entries, fetches twenty rows, and stops.

Limit  (actual time=0.06..0.31 rows=20)
  ->  Index Scan Backward using books_pub_date_idx on books
        (actual time=0.05..0.29 rows=20 loops=1)
        Index Cond: (publisher_id = 41)
        Buffers: shared hit=24
 Execution Time: 0.38 ms

No Sort node. Twenty rows, twenty four pages: four in the index, three levels down plus a second leaf, and twenty for the rows.

The 3.1 seconds was the cold run; every run after it found those pages in memory and cost 290 milliseconds of almost pure CPU. Forty of those a second is 11.6 seconds of work every second on a sixteen core box, which is where the twelve cores and the 76% came from. After the index it is 40 times 0.38 milliseconds, fifteen milliseconds of work a second. Same page, same robot, same traffic, about seven hundred and fifty times less database work.

Column order is the whole game with a composite index, and there is one rule. An index serves a condition on its first column, or its first two, or its first three, and stops helping the moment you skip one. (publisher_id, published_at) serves "this publisher, by date" and also "this publisher" alone. It does nothing for "everything published last Tuesday, any publisher", because those dates are scattered all through it.

Galewatch, which collects readings from wind turbines, had this right in lesson 002. Its index on (turbine_id, recorded_at) turns the Tarrow Ridge panel from a 3.6 second scan of 7.3 gigabytes into under ten milliseconds: pick the turbine, walk its fortnight in time order. Written the other way round it would answer "what did every turbine do in this hour" and be useless for the panel the engineers actually open.

This is also where the index that is never used comes from. On Monday morning, before working any of this out, the founder did the panicked thing and ran CREATE INDEX ON books (published_at), because the query had published_at in it. Twenty five megabytes, fourteen seconds of blocked writes while it built, and the planner has never once looked at it. idx_scan in pg_stat_user_indexes counts how often each index has been used, and one at zero after a week of real traffic is a bill with no service attached.

When the scan is the right answer

Take the LIMIT off and ask for the publisher's whole list. Now the index is the wrong plan, and the planner knows it.

Reading the table front to back is a sequential scan: thirty thousand pages in order, no seeking. Two hundred and forty megabytes at lesson 002's two gigabytes a second is 120 milliseconds, and then the database throws away the 95% of rows belonging to other publishers. The index path is 25,900 pages in random order, 2.6 seconds. Twenty times worse, to read less data.

Both numbers sit on lesson 002's ladder. A sequential page costs 8 kilobytes divided by two gigabytes a second, four microseconds. A random page costs a hundred. Twenty five to one, and an index scan lives entirely on the expensive side of that ratio.

So there's a crossover, and it is lower than people expect. Selectivity is the fraction of a table a condition matches: one row in 1.2 million for an ISBN, which is what indexes are for; half the catalogue for price < 2000, which no index should go near; and five percent for publisher_id = 41, the interesting case, whose answer turned out to be "it depends on the ORDER BY".

My rule of thumb: once a condition matches more than about one row in a hundred, stop assuming an index helps and go and read the plan. Postgres does better than that: it keeps statistics on how many distinct values a column has and how physically clustered they are. The second is called correlation, and it is why Marlow's case is as bad as it is. The catalogue was loaded alphabetically by title over three years of distributor feeds, so a publisher's titles are sprinkled through all thirty thousand pages. Load the same table grouped by publisher and those sixty thousand rows would sit in fifteen hundred adjacent pages, read almost sequentially, and none of this lesson would have happened.

Same query, same index, same row count, two orders of magnitude, decided by the order somebody inserted the rows three years ago. I have never met anyone who guessed that one first time.

Two caches, and only one of them is in your config file

Buffers: shared hit=412 read=25718 needs unpacking, because "read" does not mean what it says.

Postgres keeps its own cache of pages, the buffer pool, sized by one setting; Marlow's is 8 gigabytes, from lesson 001. A hit is a page found there. A read is a page that was not, so Postgres asked the operating system for it.

But the operating system has a cache too. Box A has 64 gigabytes and Postgres is using 8 for the pool, so the other 56 are largely the kernel's, holding recently used file pages. A read the kernel serves out of that is a memory copy, a few microseconds. A read that actually reaches the SSD is a hundred. EXPLAIN cannot tell them apart and reports both as read.

Which is why Friday evening's two measurements were both true. The first run missed both caches and went to the disk 25,718 times. The second found those same twenty six thousand pages, 209 megabytes, sitting in the buffer pool. The founder was not fooled by a bad measurement. They were fooled by a good one, taken twice.

Now the thing lessons 001 and 002 kept pointing at. The working set is the pages your queries actually touch, not the data you store. Marlow's was 14 gigabytes, comfortably inside a 32 gigabyte box, until full text search over descriptions and reviews took it past 40 and the catalogue got slow on a Tuesday with no traffic spike and no code change. Everybody remembers August's resize to 64 gigabytes as a capacity upgrade. It was a cache resize, and nobody called it one.

Below that line, every page a query wants is in memory and query time is CPU, which climbs with load the way lesson 001's hockey stick says. Above it, queries evict each other's pages, so adding traffic raises the miss rate as well as the queue, and the same plan gets slower as the shop gets busier, with nothing in your code to explain it. Crossing the line gives you a different curve, not a worse point on the same one.

Postgres has one defence worth knowing. A sequential scan of a table larger than a quarter of the buffer pool runs through a tiny 256 kilobyte ring of buffers rather than the whole pool, so one big scan cannot flush everything the way lesson 008's crawler flushed Marlow's Redis. Marlow's 240 megabyte books table is well under a quarter of 8 gigabytes, gets no protection, and its scans really do march through the pool. Galewatch's 7.3 gigabyte fortnight is what the ring was built for.

What every index costs you

Indexes are not free, and the bill arrives on the write path where nobody is looking.

Space first, because it is the easy one. Monday's composite index is about thirty five megabytes against a 240 megabyte table: twelve bytes of key plus each entry's header and pointer is twenty eight bytes, times 1.2 million, plus the slack a B-tree leaves so inserts need not split pages. Cheap. An inverted index over 1.2 million descriptions is not cheap at all; lesson 045 opens that structure up.

The bigger cost is per write. An insert writes the row and then one entry in every index, in the right place in each, inside the same transaction. Which is why bulk loading into an indexed table is slow, and why people drop indexes before a big import and rebuild them after.

Updates have a wrinkle. Postgres never modifies a row in place; an update writes a new version, so every index pointing at that row has to point at the new one. Unless no indexed column changed and there's room on the same page, in which case Postgres links the new version to the old inside the page and leaves the indexes alone. Marlow's 06:00 import updates stock across eight thousand rows, and stock is in no index, so it takes the cheap path. Index stock to make an "in stock" filter faster and that import quietly becomes eight thousand index updates every morning.

Four indexes you can each name the query for beat twelve that accumulated during incidents.

The slow queries that never appear in the slow query log

After Monday the founder turned on Postgres's slow query log at two hundred milliseconds, which is a good instrument and cannot see the next problem at all.

Lesson 009's split had gone in the week before: the book page keeps a cached shell for a day and reads stock and price fresh from the row, about a fifth of a millisecond. The publisher page does the same per result: one query for the twenty titles, then twenty primary key reads for their stock counts.

Twenty one queries. None of them slow. All of them individually invisible.

The interesting number is the count. Postgres lives on box A and box B runs only the application, so for the half of requests box B serves, each of those twenty one queries is a round trip across the data centre, half a millisecond from lesson 002's ladder, paid one after another because the code asks for the next stock count only once the last comes back. Ten and a half milliseconds of waiting around four and a half milliseconds of work. The buyers' reorder view shows two hundred titles a page: 201 queries, a hundred milliseconds of pure round trips, not one line in the slow query log.

This is N+1: one query for the list, then one per row. It is the most common performance bug in production code, and per-query instruments are structurally blind to it, because no individual query is slow. Log the statements each request issues and alarm on the ninety ninth percentile; that one number finds N+1 in code you have never read.

The fix is to ask once. WHERE isbn = ANY($1) with twenty ISBNs is one round trip instead of twenty, and a join does the same in one hop. What I would not do is reach for a join every time: join an order to its twenty lines, each line to its title and each title to its three reviews, and the database hands you sixty rows carrying the order's fields sixty times over. Count round trips, count returned bytes, then pick.

Ninety six connections to keep one busy

One more number, because it ends most first databases and does not look like a performance problem when it arrives.

Lesson 001 gave Marlow four application processes holding pools of twenty five Postgres connections each, against max_connections of 100, and lesson 006 cut the pools to twelve per process when box B arrived, so the fleet now asks for 96 of the 100. Galewatch, whose ingest boxes hold twenty five too, gets "too many connections" on its fifth box while every machine sits at 15% CPU.

So how many connections does Marlow actually need?

Lesson 002's busy room answers it. Concurrency equals arrival rate times service time. At the Christmas peak of four hundred requests a second, 384 are book pages costing one 0.2 millisecond row read each, and sixteen are full text searches at about sixty milliseconds. That's 384 times 0.0002 plus 16 times 0.060, which is 1.04 seconds of database work per second, and the shell rebuilds that still miss the cache do not change the order of it.

One connection's worth. Marlow reserves ninety six.

The searches are the whole of it: 0.96 of that 1.04. Lesson 006 had one request in twenty five costing thirty times the rest, and now that a page is a single row read, measured in database work alone the ratio is three hundred to one.

Raising max_connections to 500 is the obvious move and the wrong one. Every Postgres connection is an operating system process with its own private memory, a few megabytes idle and considerably more while it sorts, and the server's bookkeeping grows as backends multiply. Throughput against active connections rises, flattens somewhere around two to four times the core count, then falls. On sixteen cores that is thirty two to sixty four, not five hundred.

The tool is a connection pooler: a small process between the application and the database that keeps a handful of real server connections and lends one out for each transaction. Five hundred clients, twenty server connections, and the twenty busy rather than idle. The price is that a connection is no longer yours for a whole session, so anything that assumed one breaks: session level advisory locks, a SET you expected to persist, temp tables, LISTEN and NOTIFY. Better known before you turn it on.

Stagefront, the ticketing service where two hundred thousand people press the same button at 10:00, has no choice here. Lesson 006's twenty on-sale boxes, each with the ordinary pool of twenty five, want five hundred connections from a database that can usefully run a few dozen.

The deepest reason to care has nothing to do with memory. A pool is where you choose whether requests queue in your own process, where you can see them, shed them and return a fast 503, or inside the database, where a queued query holds a backend and you find out from a graph. A pool that is too big does not remove the queue. It moves it somewhere more expensive. Lesson 041 owns that properly.

Recap

Rows examined against rows returned is the size of your mistake. Sixty thousand examined to return twenty is three thousand rows touched for every one that mattered, and no hardware fixes a ratio.

The ORDER BY is part of the index. A Sort above a scan means every matching row had to be fetched before the first result could come back, which is why LIMIT 20 saved Marlow nothing. Match the filter, then the sort order.

An index pays while your matches stay well under the table's page count. Sixty thousand rows scattered over thirty thousand pages land randomly on twenty six thousand of them: 2.6 seconds, against 120 milliseconds to read the table in order.

Two caches, and only one of them is in your config file. EXPLAIN calls a page missing from Postgres's 8 gigabyte pool a read whether the kernel had it in the box's other 56 gigabytes or the SSD went and got it. Which is how one query honestly measured 3.1 seconds and 290 milliseconds ten seconds apart.

Working set against RAM is a change of shape, not of speed. Below the line, load costs CPU and follows lesson 001's hockey stick. Above it, queries evict each other, so more traffic buys a worse hit rate as well as a longer queue.

Every index is paid for on the write path. One entry per index per insert, and an update touches every index holding a column it changed. An index no query uses is a bill with no service attached, and idx_scan at zero names them.

N+1 is a query count problem, so per-query instruments are blind to it. Two hundred and one queries at a fifth of a millisecond never trip a slow query log set at two hundred, and still cost a hundred milliseconds of round trips. Count statements per request.

Ninety six connections to keep one busy. Marlow's Christmas peak needs 1.04 seconds of database work a second and reserves 96 of Postgres's 100 to deliver it. Connections are processes, throughput peaks near a small multiple of the core count, and a pooler's real job is choosing where the queue forms.

Check your understanding

1. A query filters on status = 'unshipped' and sorts by created_at DESC with LIMIT 50, over 40 million orders of which 3,000 are unshipped. Say which index you would create, in which column order, and what the plan should look like. Then say what changes if the filter becomes status IN ('unshipped', 'packing').

2. Galewatch's engineers want, for the Tarrow Ridge wind farm, the five turbines with the lowest output in the last hour. That farm's readings table holds fourteen days at 30 rows a second across its 60 turbines. Work out roughly how many rows the query must examine, and whether an index gets that number down.

3. The founder proposes caching the publisher page for ten minutes instead of adding the index, since lesson 008 said a cache removes load from the origin. Give the number that decides it, and say what the cache would have done to Sunday's crawler.

4. A service reports shared hit=8 read=119000 and 4.2 seconds on its main query, then shared hit=119008 read=0 and 310 milliseconds when you run it again. List everything you can conclude, and what you would measure next before changing anything.

5. A team raises max_connections from 100 to 600 because their application was throwing pool timeouts, and the timeouts stop. Two weeks later the database falls over at a peak with no slow queries in the log. Explain what most likely happened, and what you would have done on the day of the timeouts.

Next lesson

011 Read Replicas: Reading From a Copy. Postgres has been alone on box A since lesson 005 and today it was still the thing running out of CPU while the application boxes idled; next lesson adds a second copy that can answer reads, and finds out which of Marlow's reads are allowed to use it.