Что показал медленный лог за неделю
Включил на неделю лог медленных запросов с порогом в секунду. Ожидал увидеть пару тяжёлых аналитических выборок. Увидел другое.
Что оказалось наверху
Первое место по суммарному времени занял запрос, который сам по себе выполняется за 40 миллисекунд. Просто его вызывают восемьдесят тысяч раз в сутки — по одному разу на каждую строку в цикле приложения. Классический N+1, только не в ORM, а в самописном скрипте выгрузки.
Сортировка не по длительности, а по произведению — вот что стоит смотреть:
SELECT
substring(query, 1, 70) AS q,
calls,
round(total_exec_time::numeric / 1000, 1) AS total_sec,
round(mean_exec_time::numeric, 1) AS mean_ms
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 15;Запрос на 40 мс, вызванный 80 000 раз, съедает 53 минуты в сутки. Запрос на 8 секунд, вызванный дважды, — 16 секунд. Первый в глаза не бросается, второй все обсуждают.
Вторая находка
Несколько запросов внезапно замедлялись в одни и те же часы. Совпало с окном ночного бэкапа: план не менялся, менялась доступная дисковая полоса. Лечится не переписыванием SQL, а разведением расписаний.
Это к вопросу о том, почему стоит смотреть на время выполнения вместе с меткой времени, а не только на агрегаты за период. Усреднение прячет ровно такие вещи.
Что поменял
- N+1 в выгрузке заменил на один запрос с
INи разбором на стороне приложения — суммарно 53 минуты превратились в 12 секунд; - бэкап сдвинул на час, чтобы не пересекался с ночным пересчётом витрин;
- порог в логе оставил включённым, но поднял до трёх секунд — иначе он сам становится источником нагрузки на диск.
Последнее не мелочь: на нагруженной базе лог с порогом в 100 мс пишет столько, что заметно влияет на то, что измеряет.