Бывший коллега написал в пятницу вечером: в их приложении раздел «Мои заказы» открывается секунды две, а в обеденный пик и дольше. Бэкенд на Go, база PostgreSQL, в таблице orders около двенадцати миллионов строк. Разработчики грешили на сеть. Я попросил доступ на чтение и полчаса тишины.

Такие истории я люблю: обычно они заканчиваются одним индексом. Здесь понадобилось два, и первый потом пришлось удалить. Цифры я упростил, чтобы читалось, ход событий оставил как был.

Сначала найти запрос

Искать медленный запрос в коде глазами бесполезно: запросов там сотни. Для этого есть расширение pg_stat_statements, оно копит статистику по каждому виду запроса. Подключается оно через shared_preload_libraries с перезапуском сервера, на чужом проде это не пять минут. Тут оно стояло, но туда никто не заглядывал.

SQL
SELECT calls, round(mean_exec_time::numeric, 1) AS mean_ms, query
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 5;

Первым с огромным отрывом шёл запрос с 18 342 вызовами по 1,9 секунды в среднем, список для вкладок «Оплаченные», «Отменённые», «Возвраты»:

SQL
SELECT id, created_at, status, total
FROM orders
WHERE customer_id = $1 AND status = $2
ORDER BY created_at DESC
LIMIT 20;

Что показал EXPLAIN (ANALYZE, BUFFERS)

Голый EXPLAIN показывает план и оценки. С ANALYZE запрос выполняется, и рядом с оценками встают фактические цифры. BUFFERS добавляет, сколько страниц по 8 КБ пришлось прочитать. Я взял клиента из жалобы в поддержку и выключил в сессии параллельных воркеров (SET max_parallel_workers_per_gather = 0), чтобы план влез в экран:

Текст
Limit  (cost=381216.32..381216.35 rows=9 width=36) (actual time=2861.790..2861.796 rows=20 loops=1)
  ->  Sort  (cost=381216.32..381216.35 rows=9 width=36) (actual time=2861.788..2861.791 rows=20 loops=1)
        Sort Key: created_at DESC
        Sort Method: quicksort  Memory: 27kB
        ->  Seq Scan on orders  (cost=0.00..381216.18 rows=9 width=36) (actual time=412.118..2861.734 rows=37 loops=1)
              Filter: ((customer_id = 48213) AND (status = 'paid'::text))
              Rows Removed by Filter: 12038375
              Buffers: shared hit=32418 read=168222
Execution Time: 2861.902 ms

Строки Buffers у верхних узлов и время планирования я вырезал: там суммы по детям.

План читается изнутри наружу. В самой глубине Seq Scan, чтение всей таблицы подряд. Двенадцать миллионов строк прошли через фильтр ради 37 заказов одного человека.

Потом пары чисел. В скобках с cost то, чего ждал планировщик, с actual — что вышло. Ждал 9 строк, получил 37, обычная погрешность. Буферы переводятся в объём умножением: 200 640 страниц по 8 КБ — около полутора гигабайт ради двадцати строчек. На проде воркеры читали те же гигабайты втроём, потому и 1,9 секунды вместо 2,9.

Индекс по status был, и планировщик справедливо его игнорировал: оплаченных около двух третей. А индекса по customer_id не было. Внешний ключ на клиентов стоял, и все думали, что индекс прилагается. В PostgreSQL для ссылающейся колонки внешний ключ индекс сам не создаёт.

В любом плане я сразу ищу три места:

  • оценку rows рядом с фактической: в разы — терпимо, в сотни раз — пора в статистику;
  • Rows Removed by Filter и Buffers — сколько строк и страниц прочитано зря;
  • узел Sort под Limit: база сортирует всё, чтобы взять двадцать.

Индекс по клиенту и один неудобный клиент

Очевидный ход — индекс по customer_id. Ребята выкатили его тем же вечером (как — ниже), и обычный клиент стал отвечать за миллисекунду. В плане появилась пара Bitmap Index Scan и Bitmap Heap Scan: по индексу собирается карта страниц со строками клиента, потом эти страницы читаются из таблицы.

Статистику сбросили, через час среднее было 9 мс, и коллега написал «с меня пиво». Но индекс я всегда проверяю на самом тяжёлом значении ключа и на реплике посчитал, у кого заказов больше всех. Наверху оказался оптовик: три недели назад подключился через API, создаёт две-три тысячи заказов в день и раз в минуту опрашивает этот список. Заказов у него 58 040. Низ его плана (сверху те же Sort и Limit, итог 96 мс):

Текст
Bitmap Heap Scan on orders  (cost=4.66..58.07 rows=9 width=36) (actual time=6.913..88.551 rows=41312 loops=1)
  Recheck Cond: (customer_id = 900417)
  Filter: (status = 'paid'::text)
  Rows Removed by Filter: 16728
  Heap Blocks: exact=6917
  Buffers: shared hit=4105 read=2858
  ->  Bitmap Index Scan on orders_customer_id_idx  (cost=0.00..4.66 rows=13 width=0) (actual time=4.102..4.102 rows=58040 loops=1)
        Index Cond: (customer_id = 900417)

Планировщик ждал 13 строк, пришло 58 040. Это уже слепота. Распределение данных планировщик берёт из статистики, а её ANALYZE собирает по выборке, по умолчанию 30 тысяч строк. Клиента, которого там нет, он считает средним, а у среднего около тринадцати заказов.

По pg_stat_user_tables последний автоанализ прошёл 24 дня назад, до появления оптовика. Автовакуум по умолчанию берётся за анализ, когда изменилось 10 % таблицы плюс 50 строк, то есть здесь 1,2 миллиона. Набралось 1,1. Ждать я не стал и попросил их дежурного запустить ANALYZE orders: он читает только выборку, запись не блокирует и идёт секунды. Оценка стала 57 600.

План остался прежним, но теперь хотя бы не врал о том, что происходит: ради двадцати строк база поднимает сорок одну тысячу, сортирует и почти все выбрасывает. И так раз в минуту.

Порядок колонок в составном индексе

Нужен индекс, где строки клиента в одном статусе уже лежат по дате. B-tree упорядочивает записи по первой колонке, внутри неё по второй и так далее:

SQL
CREATE INDEX CONCURRENTLY orders_customer_status_created_idx
    ON orders (customer_id, status, created_at);

Записи пары «клиент + статус» лежат в нём подряд, по возрастанию даты. Базе остаётся встать в конец куска и прочитать двадцать штук назад. DESC в индексе писать не нужно, b-tree читается в обе стороны.

Текст
Limit  (cost=0.56..22.24 rows=20 width=36) (actual time=0.041..0.088 rows=20 loops=1)
  ->  Index Scan Backward using orders_customer_status_created_idx on orders  (cost=0.56..42455.10 rows=39168 width=36) (actual time=0.039..0.083 rows=20 loops=1)
        Index Cond: ((customer_id = 900417) AND (status = 'paid'::text))
        Buffers: shared hit=21
Execution Time: 0.112 ms

Ни сортировки, ни фильтра. Условие целиком ушло в Index Cond, прочитана 21 страница вместо почти семи тысяч.

Нарисованная ручкой схема дерева индекса в тетради в клетку
Рисовал коллеге по видеосвязи, как лежат записи в составном индексе. Стрелки кривые, зато понял.

Правило у меня такое: колонки с равенством впереди, колонка сортировки последней. Почему, лучше всего видно на неправильных вариантах.

  • (created_at, customer_id, status). Порядок по дате для всей таблицы, заказы клиента размазаны по индексу от начала до конца.
  • (customer_id, created_at, status). Уже неплохо, но статусы внутри перемешаны, и база идёт назад, проверяя статус у каждой записи. На «Оплаченных» это почти бесплатно, а на «Возвратах», где у оптовика несколько десятков заказов, придётся перебрать десятки тысяч записей.
  • (status, customer_id, created_at). Этому запросу подходит не хуже, но вкладке «Все заказы», где фильтр только по клиенту, нужен индекс, который начинается с customer_id.

Заодно стало ясно, что первый индекс, по одному customer_id, лишний: составной начинается с той же колонки и справляется почти так же, а каждый лишний индекс — работа на каждой вставке.

Как это выкатывали

Обычный CREATE INDEX на время построения блокирует запись в таблицу: читать можно, а новые заказы встанут. CREATE INDEX CONCURRENTLY запись не держит, зато проходит таблицу дважды и ждёт завершения транзакций, которые её трогали. Составной строился минут шесть.

Внутри транзакции такая команда не работает. Миграции у них на goose, он по умолчанию заворачивает каждый файл в транзакцию, и первый прогон кончился ошибкой CREATE INDEX CONCURRENTLY cannot run inside a transaction block. Лечится строкой -- +goose NO TRANSACTION в начале файла. Руками в psql индексы на проде я не создаю: через полгода никто не вспомнит, откуда они.

Если построение прервётся, останется индекс с пометкой INVALID: запросам не помогает, а при записи обновляется. Поэтому после миграции я смотрю \d orders. Старые индексы по customer_id и status убрали через DROP INDEX CONCURRENTLY, отдельной миграцией с той же пометкой. Перед этим проверили в pg_stat_user_indexes, что у индекса по статусу счётчик сканов на нуле. И на реплике тоже, статистика там своя.

Назавтра я снова открыл pg_stat_statements. Наш запрос уехал далеко вниз, со средним меньше миллисекунды. Наверху теперь ночная выгрузка для бухгалтерии, она раз в сутки читает всю таблицу. Её я пока не трогаю: работает ночью, и никто её не ждёт.