Временные файлы сортировки заполнили диск базы за четыре минуты

MAATRIX

В десять утра понедельника, в первый рабочий день после недели отпусков, приложение легло целиком: и запись, и чтение. Никто не трогал код, релизов не было, нагрузка на первый взгляд обычная. А диск базы данных за четыре минуты дошёл от «есть запас» до «нет ни байта». Ниже — как мы это раскапывали, какие версии отбросили и что оказалось настоящей причиной.

Что случилось: диск обнулился за четыре минуты

Алерт из мониторинга диска прилетел в 10:03: свободное место на разделе с данными PostgreSQL упало с 32% до 2% за одну проверку (интервал опроса — минута). Через ещё одну минуту — 0%. PostgreSQL перестал принимать новые подключения с ошибкой could not write to file: No space left on device, а часть уже открытых транзакций начала падать с could not extend file — база фактически встала, потому что не могла писать ни данные, ни WAL.

Первая реакция была стандартной: посмотреть, что заняло место. du -sh по каталогу данных ожидаемо долго не отвечал (диск был забит под ноль, и даже чтение метаданных подтормаживало), поэтому пошли через df -h и lsof, чтобы понять, какие файлы реально держат место:

df -h /var/lib/postgresql
Filesystem      Size  Used Avail Use% Mounted on
/dev/sdb1       200G  200G     0 100% /var/lib/postgresql

lsof +L1 | grep postgres | sort -k7 -n -r | head -20

lsof +L1 показывает файлы, у которых есть открытые дескрипторы, но нет ссылок в файловой системе (то есть они уже удалены, но место не освобождено, пока их держит процесс) — и по-настоящему живые открытые файлы. В выводе оказалось два десятка файлов вида base/pgsql_tmp/pgsql_tmp12345.3.sharedfileset/i0.p0.0 размером от 3 до 6 ГБ каждый. Это временные файлы сортировки PostgreSQL, и именно они съели весь запас диска.

Что показывали логи и метрики

В логе PostgreSQL, если включено логирование временных файлов, каждая такая операция оставляет след. У нас log_temp_files был выставлен не в 0 (логировать все), а в 10MB — то есть логировались только файлы крупнее 10 МБ, и таких записей за последний час набралось несколько сотен:

LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp12345.3.sharedfileset/i0.p0.0", size 3221225472
STATEMENT:  SELECT o.id, o.created_at, o.customer_id, oi.sku, oi.qty, oi.price
            FROM orders o JOIN order_items oi ON oi.order_id = o.id
            WHERE o.created_at >= now() - interval '18 months'
            ORDER BY o.created_at DESC, oi.sku;

Метрики pg_stat_database.temp_files и pg_stat_database.temp_bytes (кумулятивные счётчики с момента последнего сброса статистики) подтвердили масштаб: за час до инцидента temp_bytes вырос почти на 90 ГБ. Это агрегат по всей базе, без разбивки по запросу, но вместе с текстом STATEMENT из лога он сразу указал на подозреваемого — запрос отчёта по заказам за полтора года без LIMIT и без индекса, покрывающего сортировку.

Через pg_stat_activity мы увидели, что в момент падения было открыто 11 одинаковых по тексту запросов почти в одну секунду:

SELECT pid, state, query_start, left(query, 80)
FROM pg_stat_activity
WHERE state != 'idle'
ORDER BY query_start;

11 параллельных сессий с одним и тем же тяжёлым JOIN + ORDER BY — это и была настоящая причина скорости заполнения диска: не один медленный запрос, а внезапный залп одинаковых запросов один за другим.

Гипотезы, которые отбросили

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

• Утечка WAL из-за зависшей репликации или забытого слота. Проверили pg_replication_slots — активных слотов не было, pg_wal весил в пределах нормы (около 4 ГБ), рост шёл не там. Похожая, но другая история описана в статье про забытый слот репликации, который не давал чистить WAL — у нас это не подтвердилось.
• Зависший бэкап или дамп, который пишет во временный каталог. Проверили cron и systemd-таймеры: ближайший pg_dump был запланирован на 3 часа ночи и отработал штатно за пять часов до инцидента, никаких параллельных job в 10 утра не было.
• Runaway autovacuum, раздувший рабочие файлы. pg_stat_progress_vacuum был пуст, активных vacuum-процессов не было. Автовакуум на этой базе — отдельная больная тема, но не в это утро.
• Ротация логов или диагностика, забившая диск логами приложения. Каталог логов был на отдельном разделе (/var/log), не пересекался с разделом данных PostgreSQL — эта версия отпала за минуту по df -h.
• Утечка файловых дескрипторов в приложении. Проверили lsof на стороне бэкенд-сервиса — ничего аномального, счётчик открытых файлов в норме.

Отбрасывание версий заняло больше времени, чем сам поиск правильной причины: каждую нужно было не просто предположить, а подтвердить командой и цифрой, иначе легко зациклиться на удобной, но неверной догадке.

Настоящая причина: залп одинаковых запросов и work_mem по умолчанию

Совпадение по времени и логам дало ответ. У аналитиков в компании есть внутренний BI-дашборд с отчётом по заказам за полтора года. После недели отпусков сотрудники в течение одной минуты открыли этот дашборд почти одновременно — часть с ноутбуков, часть переоткрыли ранее сохранённые вкладки с автообновлением раз в 5 минут. Дашборд не кэшировал результат и не ограничивал параллелизм на бэкенде: каждое открытие страницы порождало отдельный запрос напрямую к базе.

Сам запрос — JOIN таблицы заказов (около 40 млн строк) с таблицей позиций заказа, фильтр по полутора годам и сортировка по двум столбцам без подходящего составного индекса. Планировщик честно выбирал Hash Join и внешнюю сортировку (external merge, Disk) — это видно в EXPLAIN (ANALYZE, BUFFERS), если прогнать такой запрос отдельно:

Sort  (cost=... rows=6200000 width=64) (actual time=... rows=6187341 loops=1)
  Sort Key: o.created_at DESC, oi.sku
  Sort Method: external merge  Disk: 3145728kB
  ->  Hash Join  (cost=... )

work_mem на сервере стоял в значении по умолчанию — 4 МБ. Для сортировки шести с лишним миллионов строк с учётом ширины строки требовалось в разы больше памяти, чем позволял work_mem, поэтому PostgreSQL закономерно уходил во внешнюю сортировку на диске — это штатное и ожидаемое поведение при нехватке памяти под операцию, не баг. Проблема была не в том, что сортировка ушла на диск сама по себе, а в том, что она делала это одновременно в 11 сессиях, и каждая создавала свой независимый набор временных файлов на несколько гигабайт. Один такой запрос сервер бы пережил без проблем — 11 одновременных исчерпали 60 ГБ свободного места меньше чем за четыре минуты.

Похожая механика — один тяжёлый запрос без ограничения результата, который валит соседние процессы, — разбиралась и в другом инциденте: один запрос без LIMIT положил реплику, а вместе с ней все отчёты. Разница в том, что там реплика легла из-за нагрузки на CPU и I/O, а здесь именно диск обнулился из-за параллельных временных файлов — смежные, но разные по механике истории.

Почему PostgreSQL вообще пишет временные файлы на диск

Стоит понимать механику, а не запоминать её как «магию», которая иногда стреляет. work_mem — это лимит памяти на одну операцию сортировки или хеширования в рамках одного запроса, а не на весь запрос и не на всю сессию. Если запрос делает несколько сортировок или хешей параллельно (например, сортировка плюс хеш-джойн), каждая операция может занять до work_mem, и суммарная память на один запрос легко превышает номинальный лимит в несколько раз.

Операции, которые могут выйти за work_mem и уйти на диск:

• ORDER BY без покрывающего индекса — классическая внешняя сортировка;
• GROUP BY и DISTINCT, если планировщик выбирает hash-агрегацию, а не сортировку по индексу;
• HASH JOIN на больших таблицах — хеш-таблица может не поместиться в work_mem;
• оконные функции (ROW_NUMBER() OVER (...), RANK()) с сортировкой по большому набору строк;
• CREATE INDEX и REINDEX на крупных таблицах — тоже сортировка, тоже может уйти на диск, если maintenance_work_mem мал.

Куда эти файлы пишутся — управляется параметром temp_tablespaces. Если он не задан, временные файлы попадают в тот же табличный пространство, что и данные, то есть физически на тот же диск, что делает такой сценарий особенно опасным: диск с боевыми данными может отказать не из-за роста самой базы, а из-за одной неудачной комбинации запросов.

Что изменили после инцидента

Изменения разложили на три уровня: немедленный фикс, защита от повтора и профилактика на будущее.

Немедленно после инцидента:

• Добавили индекс, покрывающий фильтр и сортировку отчёта: CREATE INDEX CONCURRENTLY idx_orders_created_at ON orders (created_at DESC); — сортировка по индексу вместо внешней сортировки на диске.
• Переписали запрос дашборда с явным LIMIT и пагинацией, вместо выгрузки всех строк за полтора года разом.
• На стороне BI-дашборда добавили простое кэширование результата на 5 минут и дедупликацию одинаковых параллельных запросов — теперь 11 открытых вкладок формируют один запрос к базе, а не одиннадцать.

Защита от повтора того же класса проблем:

• temp_tablespaces вынесли на отдельный диск, физически не связанный с диском данных, чтобы всплеск временных файлов не мог обнулить место под саму базу.
• Включили log_temp_files = 0, чтобы логировать вообще все временные файлы, а не только крупнее 10 МБ — так следующий похожий эпизод виден сразу, а не постфактум.
• statement_timeout для сессий отчётного пользователя ограничили разумным потолком, чтобы аномально тяжёлый запрос обрывался, а не тянул ресурсы неограниченно.
• Осторожно подняли work_mem для роли, от которой идут аналитические запросы (через ALTER ROLE ... SET work_mem, а не глобально для всего кластера) — глобальное повышение опасно тем, что умножается на число одновременных сортирующих операций по всем сессиям и может съесть память сервера вместо диска.

Профилактика на уровне мониторинга — здесь можно почитать про настройку мониторинга диска на VPS, если такого алертинга ещё нет:

• Порог алерта на свободное место снизили с «осталось меньше 10%» до «осталось меньше 25%» и добавили алерт на скорость изменения (падение больше чем на 5% за минуту) — именно скорость, а не абсолютное значение, в этот раз была тревожным сигналом за несколько минут до отказа.
• Разбор похожих граблей с обычным заполнением диска — в статье диск заполнился на 100%, что отвалилось первым: PostgreSQL реагирует на нехватку места не всегда одинаково предсказуемо, и полезно заранее знать порядок отказов.
• В целом тюнинг work_mem, maintenance_work_mem и связанных параметров подробнее разобран в статье про частые ошибки тюнинга PostgreSQL на сервере — там же обсуждается, почему поднимать work_mem глобально рискованно.

Частые вопросы