Профилирование Symfony в проде: разбор инцидента с деградацией

Симптом выглядел безобидно: p95 времени ответа на одном из эндпоинтов вырос с 180 мс до 3,2 секунды. CPU на воркерах держался около 40%, память не текла, база отвечала быстро — pg_stat_statements показывал, что самый тяжёлый запрос укладывается в 12 мс. Приложение — API на Symfony 6.4 под PHP 8.2, PHP-FPM за Nginx, около 300 одновременных запросов в пике. Web Profiler в проде выключен, как и должно быть. Ниже — как мы локализовали причину за один рабочий день и почему привычная интуиция «раз медленно, значит база» здесь только мешала.

Почему обычный профайлер не помогает в проде

Symfony Profiler и панель отладки живут в дев-режиме. Включать APP_ENV=dev на боевом сервере нельзя: это меняет обработку ошибок, отключает кеш контейнера и сам по себе замедляет всё в разы. То есть инструмент, которым удобно смотреть таймлайн запроса на ноутбуке, в бою недоступен по определению.

В проде остаётся три источника правды:

• APM-агент или сэмплирующий профайлер, который снимает стек с работающих процессов — Blackfire, Tideways, XHProf/Excimer;
• метрики самого приложения — таймеры вокруг подозрительных участков через Symfony Stopwatch, выгружаемые в Prometheus или лог;
• логи с трассировкой запроса и корреляционным идентификатором.

Мы пошли по второму и третьему пути: агента на этом контуре не было, а разворачивать его под инцидент — терять время.

Шаг первый: убедиться, что дело не в базе

Первое подозрение всегда падает на SQL. Проверять его нужно фактами, а не догадкой. В Doctrine 2.x/3.x есть SQLLogger (в 3.x — через middleware и DebugStack-подобные обёртки), но в проде его держать дорого. Мы сделали проще: включили log_min_duration_statement = 100 в PostgreSQL на пять минут и посмотрели, что попадёт в лог.

В лог медленных запросов не попало ничего с этого эндпоинта. Значит, 3 секунды тратятся не в базе. Это сузило зону поиска сильнее, чем любой профайлер.

Вывод: время уходит внутри PHP-процесса между получением данных и отдачей ответа. Осталось найти где.

Шаг второй: расставить таймеры Stopwatch

Symfony поставляет компонент symfony/stopwatch, тот же, что питает таймлайн профайлера. Его можно использовать вручную в любом коде, без дев-режима. Мы обернули ключевые участки контроллера и сериализации, а результат писали в лог с уровнем info только когда общее время превышало порог — чтобы не залить логи.

<?php
// Symfony 6.4, PHP 8.2
// Фрагмент внутри действия контроллера

use Symfony\Component\Stopwatch\Stopwatch;
use Psr\Log\LoggerInterface;

public function list(LoggerInterface $logger): Response
{
    $stopwatch = new Stopwatch(true); // true — включить сбор категорий

    $stopwatch->start('fetch');
    $orders = $this->orderRepository->findActiveForDashboard();
    $stopwatch->stop('fetch');

    $stopwatch->start('serialize');
    $payload = $this->serializer->serialize($orders, 'json', [
        'groups' => ['dashboard'],
    ]);
    $stopwatch->stop('serialize');

    // Логируем только медленные ответы, чтобы не забить лог
    $total = 0;
    foreach ($stopwatch->getSectionEvents('__root__') as $name => $event) {
        $total += $event->getDuration();
    }
    if ($total > 1000) { // миллисекунды
        foreach ($stopwatch->getSectionEvents('__root__') as $name => $event) {
            $logger->info('sw', [
                'span' => $name,
                'ms' => round($event->getDuration(), 1),
                'mem_mb' => round($event->getMemory() / 1048576, 1),
            ]);
        }
    }

    return new JsonResponse($payload, 200, [], true);
}

Через несколько минут в логах медленных ответов проступила картина: fetch — 40-60 мс, а serialize — 2800-3000 мс. Виновата была не выборка, а сериализация.

Шаг третий: почему сериализация съела три секунды

Запрос возвращал около 400 объектов заказа. По отдельности каждый сериализуется быстро. Проблема была в связях: у каждого заказа сериализатор дёргал связанного клиента и его адреса, а те были lazy. Формально в логе PostgreSQL этих запросов не было — потому что порог мы ставили 100 мс, а каждый доп-запрос укладывался в 2-3 мс. Но их было около 800 штук на один HTTP-запрос: классический N+1, размазанный так, что ни один запрос не выглядит медленным.

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

Как это проявляется именно в Doctrine

Ленивая загрузка удобна, пока вы работаете с одним объектом. Как только сериализатор обходит коллекцию и трогает каждую связь, вы получаете по запросу на связь. pg_stat_statements агрегирует их в одну строку с большим calls и маленьким средним временем — и вы легко пройдёте мимо, если смотрите только на топ по суммарному времени.

Что исправили

Решение — вытянуть связи одним запросом и не давать сериализатору ходить в базу. В DQL/QueryBuilder это JOIN с addSelect, чтобы связанные сущности попали в результат сразу:

<?php
// Symfony 6.4, Doctrine ORM 2.17
// Репозиторий заказов

public function findActiveForDashboard(): array
{
    return $this->createQueryBuilder('o')
        ->addSelect('c', 'a')          // клиент и адреса едут вместе с заказом
        ->join('o.customer', 'c')
        ->leftJoin('c.addresses', 'a')
        ->andWhere('o.status = :status')
        ->setParameter('status', 'active')
        ->getQuery()
        ->getResult();
}

После деплоя serialize в тех же логах опустился до 90-120 мс, p95 эндпоинта вернулся к 200 мс. Число запросов к базе на один HTTP-запрос упало с ~800 до 3.

Инцидент, который выглядел как «медленная база», на деле был проблемой сериализации, спровоцированной ленивыми связями. Ни один отдельный запрос не был медленным — медленной была их сумма.

Инструменты, которые стоит держать наготове

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

Точную схему подключения probe и версии совместимости уточняйте в актуальной документации выбранного агента — они меняются от релиза к релизу.

Где такой разбор ломается

Метод «поставить таймеры и смотреть логи» работает, когда вы уже примерно знаете подозрительный эндпоинт. Если деградация размазана по всему приложению или проявляется случайно, ручная обвязка не поможет — нужен сэмплирующий профайлер, который снимает стек со всех процессов. Отдельная ловушка: addSelect с leftJoin по коллекции даёт декартово произведение строк, и на связях «один ко многим» с большими коллекциями это само по себе станет проблемой. Тогда разумнее грузить связи отдельным запросом через fetch mode или батчить выборку. Настройку fetch-режима сущностей — отдельная тема, здесь мы её не разворачиваем.

Что делать дальше

Не ждите следующего инцидента. Заведите на боевом контуре сэмплирующий профайлер или APM и смотрите не только на топ запросов по суммарному времени, но и на запросы с аномально большим числом вызовов — там прячется N+1. Настройте log_min_duration_statement в PostgreSQL на разумный порог как постоянную практику, а в приложении держите метрику «число SQL-запросов на HTTP-запрос»: её рост — ранний сигнал, что где-то отвалилась жадная загрузка связей.