APM-инструменты находят медленные SQL-запросы в продакшене точнее, чем ручная оптимизация по ощущениям

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

Средняя температура по больнице прячет хвост из медленных обращений

Первый обман, который расставляет APM-инструменты по местам, это среднее время ответа. Из ста обращений девяносто девять укладываются в 120 миллисекунд, а одно тянет восемь секунд, и среднее арифметическое покажет приятные 200 миллисекунд. Пользователь замечает именно хвост, а не среднее, поэтому и оптимизировать нужно хвост. Вместо средних панели смотрят на процентили: p50 описывает типичное обращение, p95 обнажает неудобное меньшинство, p99 высвечивает самые тяжёлые случаи. Задача почти всегда формулируется как сдвиг p95 и p99 вниз, а не улучшение среднего.

Второй обман тоньше. Усреднение по всем операциям приложения размывает виновника: сотни быстрых справочных обращений статистически топят один тяжёлый отчёт. Поэтому смотрят в разрезе операций: каждый эндпоинт со своими процентилями, каждая таблица со своим вкладом. Третий слой детализации это время суток: ночные пакетные задания искажают статистику, если смешивать их с дневным трафиком. Хорошая панель отделяет автоматические процессы от живых пользователей, иначе вместо оптимизации получится война с собственным планировщиком.

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

Трейс разбирает обращение на слагаемые задержки

Основной инструмент APM это распределённая трассировка. Обращение к приложению получает сквозной идентификатор trace_id и разбивается на отрезки, которые в терминах открытого стандарта OpenTelemetry называются span. Корневой отрезок начинается при приёме запроса и закрывается с отправкой ответа. Внутри лежат дочерние отрезки: обращение к базе, вызов чужого сервиса, работа с кэшем. У каждого отрезка есть время начала и конца, ссылка на родителя и атрибуты, а для обращений к базе среди атрибутов указывается db.statement с текстом SQL-запроса.

Контекст передаётся между сервисами через HTTP-заголовок traceparent, поэтому одна цепочка собирается даже после десяти переходов между приложениями. Подключается трассировка агентами автоматической инструментации для популярных фреймворков либо вручную через SDK, собирает всё коллектор OpenTelemetry, а хранят и показывают трейсы Jaeger, Tempo или коммерческие системы наблюдения. Дальше начинается самое полезное: по trace_id к трейсу приклеиваются записи журнала, так что сообщение об ошибке мгновенно приводит к полной картине вызовов.

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

Рабочий путь от аномалии в графике до исправленного SQL

Порядок разбора медленного эндпоинта отработан до автоматизма:

1. Отсортировать операции по p99 и выбрать самую заметную аномалию;
2. Открыть несколько медленных трейсов и найти самый толстый дочерний span;
3. Скопировать текст SQL-запроса из атрибута db.statement и время выполнения;
4. Воспроизвести запрос с EXPLAIN ANALYZE на стенде с боевой статистикой;
5. Найти операцию с наибольшей ценой, чаще всего последовательный просмотр большой таблицы;
6. Добавить индекс, переписать запрос или вынести тяжёлую часть из горячего пути;
7. Сверить сдвиг p99 на графике за тот же период.

Типичный первый прогон выглядит так:

EXPLAIN (ANALYZE, BUFFERS)
SELECT o.id, o.total
FROM orders o
JOIN customers c ON c.id = o.customer_id
WHERE c.email = Адрес электронной почты защищен от спам-ботов. Для просмотра адреса в браузере должен быть включен Javascript.';

и в выводе сразу видно лишнюю работу:

Seq Scan on customers c  (cost=0.00..1234.00 rows=1 width=8)
                         (actual time=0.9..11.2 rows=1 loops=1)
  Filter: ((email)::text = Адрес электронной почты защищен от спам-ботов. Для просмотра адреса в браузере должен быть включен Javascript.'::text)
  Rows Removed by Filter: 249999
  Buffers: shared hit=812

Строка с названием Rows Removed by Filter говорит сама за себя: ради одного совпадения перелопачено четверть миллиона строк. Лекарство скромное:

CREATE INDEX CONCURRENTLY customers_email_idx ON customers (email);

и тот же запрос начинает выполняться за миллисекунды. Слово CONCURRENTLY здесь не украшение: на работающей базе оно не даёт построению индекса держать блокировку на запись и останавливать соседние операции.

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

Кроме отсутствующих индексов трейсы регулярно показывают три повторяющихся греха. Первый это серия из сотен крошечных обращений к базе вместо одного, классический N+1 из ленивых связей ORM. Второй это чужой вызов внутри транзакции: пока приложение ждёт ответа внешнего сервиса, соединение с базой занято, пул исчерпывается и встают соседние операции. Третий это выборка целой таблицы ради страницы из двадцати строк, когда в запросе забыли и ограничение, и условие.

Встроенные средства СУБД подтверждают диагноз

Трейс показывает, какой запрос тяжёлый, а встроенная статистика базы объясняет, почему он тяжёлый у всех. Расширение pg_stat_statements копит по каждому шаблону запроса число вызовов и суммарное время:

CREATE EXTENSION pg_stat_statements;
SELECT query, calls,
       round(mean_exec_time::numeric) AS ms_avg,
       round(total_exec_time::numeric) AS ms_total
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 10;

Похожие запросы нормализуются в один шаблон, поэтому список из десяти строк честно показывает главные пожиратели времени. В версиях PostgreSQL до тринадцатой поля называются mean_time и total_time, в остальном путь тот же.

Когда нужен уровень отдельного выполнения, включают модуль auto_explain: он пишет план в журнал для любого запроса, живущего дольше порога:

shared_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = '500ms'
auto_explain.log_analyze = on

Опция log_analyze даёт настоящие времена выполнения, но добавляет нагрузку, поэтому на нагруженной базе её включают точечно и ненадолго. В MySQL ту же работу делает медленный журнал с порогом long_query_time и статистика performance_schema, а путь разбора одинаковый: медленный запрос из журнала находится в трейсе по своему тексту.

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

Ловушка оптимизации подряд и цена отсутствия измерений

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

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

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

Выборка трейсов, стоимость наблюдения и непрерывное профилирование

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

Стоимость остаётся, и её честно считают. Текст SQL-запроса в атрибутах занимает место и порой раскрывает структуру таблиц, поэтому секреты и персональные значения вырезают на коллекторе правилами замены. Сама приборка измеряется миллисекундами на обращение, но на горячих путях даже их проверяют замером. Отдельным слоем идёт непрерывное профилирование процессора и памяти: инструменты вроде Pyroscope с доставкой сведений через eBPF показывают, какие функции съедают секунды процессорного времени. Трассировка отвечает за ожидания и обращения к базе, профилирование за вычисления, вместе они закрывают почти всю картину медленности.

Бюджеты задержек и закрепление результата

Исправление без закрепления забывается через квартал, поэтому результат оформляют как постоянное правило. Для каждого значимого эндпоинта назначается бюджет задержки, скажем p95 не дольше 300 миллисекунд, и на его превышение настраивается оповещение. Новые сервисы подключаются к трассировке с первого дня: добавить приборку в чужой код потом труднее, чем писать с ней сразу. Релизный конвейер сравнивает процентили до и после выката, и регрессия ловится на следующий день, а не по жалобе клиента.

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

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