Как выгрузка трейсов остудила кэш PostgreSQL и положила дашборды на три часа

Сервис использует внутренний инстанс Arize Phoenix — систему наблюдаемости за LLM-приложениями. Phoenix хранит трейсы в PostgreSQL, база крутится в облаке на инстансе с 2 vCPU. В обычном режиме метрика AAS (Average Active Sessions — среднее число сессий, которые выполняют запрос или ждут ресурса) держалась около 1.0. В день инцидента она поднялась до 25, и несколько часов дашборды Phoenix отвечали с тайм-аутами.

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

AAS против числа ядер

Первая метрика для такого случая — AAS из Performance Insights. Правило чтения простое:

AAS примерно равен числу vCPU — база работает на пределе;
AAS выше числа vCPU — запросы стоят в очереди.

Потолок для инстанса был 2, фактическое значение — 25. Значит, большую часть времени сессии стояли в ожидании ресурсов. Дальше ту же нагрузку раскладывают по двум разрезам: wait events и Top SQL.

Что показали wait events

Доминировали два типа ожиданий:

IO:DataFileRead — сессия ждёт чтения страницы с диска, потому что её нет в памяти;
IPC:BufferIo — несколько бэкендов ждут одну и ту же страницу, которую кто-то уже читает в shared memory. По сути это ожидание на latch.

Такая пара почти однозначно указывает на вытеснение рабочего набора из shared_buffers, общего кэша страниц в оперативной памяти. Горячие страницы ушли, и запросы, которые раньше обслуживались из памяти, начали читать диск.

Если Performance Insights нет, похожую картину собирают из pg_stat_activity:

SELECT wait_event_type, wait_event, count(*)
FROM pg_stat_activity
WHERE state <> 'idle'
GROUP BY 1, 2
ORDER BY 3 DESC;

Снимок раз в несколько секунд в течение инцидента даёт тот же разрез по ожиданиям.

Две нагрузки в Top SQL

В Top SQL по времени совпали два запроса:

Тяжёлый агрегирующий запрос дашборда Phoenix с вкладом в AAS 14.37.
FETCH FORWARD по таблице spans — выгрузка трейсов за 22 дня, которую соседняя команда запустила курсором, порциями.

Второй запрос в сервисе никто не писал. Его автор — другая команда с доступом к той же базе.

Почему курсор по индексу опаснее последовательного скана

Тут работает деталь внутреннего устройства PostgreSQL. Последовательный скан большой таблицы (больше четверти shared_buffers) идёт через ring buffer — небольшой кольцевой буфер, который переиспользует одни и те же слоты. Такой скан почти не трогает основной кэш, даже если прочитает всю таблицу.

Чтение курсором по индексу устроено иначе. Это random I/O, и каждая прочитанная страница попадает в shared_buffers на общих основаниях. Выгрузка прогнала через кэш гигабайты холодных спанов за прошлые недели и вытеснила страницы, которые нужны были дашбордам. После этого каждый запрос Phoenix шёл на диск, отсюда IO:DataFileRead и рост AAS.

Аналитика Phoenix сама по себе базу не перегружала: шесть дней до инцидента собственная нагрузка проходила без проблем. Сломала всё конкуренция за кэш.

Проверить, кто занимает shared_buffers прямо сейчас, можно расширением pg_buffercache:

CREATE EXTENSION IF NOT EXISTS pg_buffercache;

SELECT c.relname, count(*) AS buffers
FROM pg_buffercache b
JOIN pg_class c ON b.relfilenode = pg_relation_filenode(c.oid)
WHERE b.reldatabase = (SELECT oid FROM pg_database WHERE datname = current_database())
GROUP BY c.relname
ORDER BY buffers DESC
LIMIT 10;

Если в топе внезапно оказался индекс или таблица, которую дашборды не читают, это и есть след вытеснения.

Запросы без индексов держались на тёплом кэше

Вторая причина нашлась в текстах запросов из Top SQL. Часть запросов самого Phoenix фильтровала и джойнила spans полным сканированием, без индексов. Пока кэш горячий, это почти незаметно: скан страниц в памяти дешёвый. Тот же запрос на холодном кэше превращается в чтение с диска.

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

Performance Insights показывает, кто создал нагрузку. Почему запрос её не выдержал, отвечает только план выполнения:

EXPLAIN (ANALYZE, BUFFERS)
SELECT ...;

В выводе BUFFERS видно соотношение shared hit (страница была в кэше) и read (пришлось читать с диска). Запрос с большим read и Seq Scan по крупной таблице — первый кандидат на индекс.

Медленные запросы Phoenix на больших таблицах spans — известная проблема, её обсуждают в GitHub issues репозитория Arize. Там же приводят индексы, которые ускоряют такие запросы примерно с 15 секунд до 1. В свежих версиях Phoenix read-нагрузку можно вынести на read replica.

Исправление 1: развести нагрузки по времени

Со смежной командой договорились, что тяжёлая выгрузка работает только ночью. Экспортёр получил простое правило: в бизнес-часы закрыть соединение, заснуть, потом переподключиться и продолжить с места остановки. Код Phoenix при этом не меняли.

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

Надёжнее вообще не пускать такие выгрузки в продовую базу и отправлять их на отдельный инстанс или read replica. На момент инцидента запасного инстанса не было, поэтому начали с расписания: оно бесплатное и внедряется за один разговор.

Исправление 2: частичный индекс под root-спаны

Недостающие индексы создали под конкретные запросы. Показательный случай — запросы по root-спанам, которые упирались в тайм-аут: клиент или балансировщик рвал соединение раньше, чем приходил ответ.

CREATE INDEX CONCURRENTLY ix_spans_root_trace_rowid_error
    ON spans (trace_rowid, cumulative_error_count)
    WHERE parent_id IS NULL;

Индекс частичный, потому что root-спанов мало относительно всех спанов. Он получается компактным и целиком помещается в память, то есть сам почти не участвует в борьбе за кэш.

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

Результат

После договорённости о ночном окне инцидент не повторялся. После индексов пропали тайм-ауты дашборда на 7-дневном диапазоне.

Короткий чек-лист для похожих ситуаций:

AAS выше числа vCPU — есть очередь, ищите, чего ждут сессии.
IO:DataFileRead вместе с IPC:BufferIo — рабочий набор вытеснен из кэша; в Top SQL ищите того, кто читает много холодных данных.
Курсор или index scan по большой исторической таблице прогоняет страницы через shared_buffers, в отличие от последовательного скана с ring buffer.
Full scan, который «нормально работал», мог держаться только на тёплом кэше. EXPLAIN (ANALYZE, BUFFERS) покажет это через долю read.
Расписание тяжёлых задач часто дешевле и быстрее тюнинга. Две тяжёлые нагрузки на одной базе в одно время — уже повод договориться о графике.

Отдельно про open source: Phoenix развивается быстро, и схема индексов в нём не всегда успевает за реальными объёмами данных. Если вы ставите такое приложение себе с PostgreSQL под капотом, проверяйте планы его тяжёлых запросов сами, не дожидаясь первого инцидента.