Профилирование в Symfony: где утекает время запроса

Страница каталога отдавалась за 780 мс на локальной машине с прогретым OPcache. Бизнес-логика — выборка товаров и рендер — по замерам занимала около 40 мс. Остальные 740 мс уходили на то, что в контроллере не видно: 214 SQL-запросов от ленивой загрузки Doctrine, десериализация кеша и три обращения к внешнему API внутри цикла Twig. Всё это показал профайлер, встроенный в Symfony, — без единой строки microtime() в коде.

Разберём, какие цифры даёт Symfony Profiler в dev-режиме, где он врёт, и когда пора переходить на Blackfire или XHProf. Речь про Symfony 6.4/7.x, но панели профайлера в целом стабильны с версии 5.x.

Что мерить сначала: wall time против времени внутри PHP

Первая ловушка — путать общее время ответа (wall time) со временем работы PHP. Панель Performance в профайлере показывает разбивку по секциям: инициализация ядра, работа контроллера, рендер, kernel.terminate. Но время в базе, в сети и в файловой системе внутри PHP-процесса тоже входит в эти секции — оно там, где вызов, а не отдельной строкой.

Поэтому дерево вызовов профайлера отвечает на вопрос «сколько времени провёл процесс», а не «сколько времени процессор реально считал». Для запроса, который упёрся в 214 обращений к БД, разница принципиальна: оптимизировать PHP-код бесполезно, узкое место — round-trip до базы.

Правило простое: сначала смотрите панель Doctrine и число запросов, потом всё остальное. В веб-приложении на ORM время чаще утекает в базу и сеть, а не в вычисления PHP.

Панель Doctrine: N+1 виден сразу

Панель Doctrine в тулбаре показывает три числа: количество запросов, суммарное время и число различных запросов. Если количество заметно больше различных — почти наверняка N+1. В примере с каталогом было 214 запросов при 6 различных: один запрос на список товаров и по одному на бренд каждого из 200+ товаров.

Разворачиваете список запросов — видите повторяющийся SELECT * FROM brand WHERE id = ? с разными параметрами. Лечится это на уровне запроса, а не профайлера:

// Symfony 6.4 / Doctrine ORM 3.x
// Было: ленивая загрузка бренда в цикле шаблона порождает N+1
$products = $this->productRepository->findAll();

// Стало: подтягиваем связь одним JOIN через QueryBuilder
$products = $this->productRepository->createQueryBuilder('p')
    ->addSelect('b')          // без addSelect связь останется ленивой
    ->leftJoin('p.brand', 'b')
    ->getQuery()
    ->getResult();

После правки панель показала 8 запросов вместо 214, время секции упало с ~600 мс до ~25 мс. Ключевой момент: один leftJoin без addSelect не решит проблему — Doctrine всё равно сходит за связанной сущностью отдельно. Проверяйте по числу запросов в панели, а не по коду.

Почему числа в dev завышены

В dev-режиме включён сбор данных профайлера, логирование, отключён кеш метаданных Doctrine и конфигурации. Абсолютные миллисекунды в тулбаре в dev на 30–60% выше, чем будет в prod с прогретым кешем. Поэтому dev-профайлер полезен для относительных выводов: что тяжелее чего, где N+1, сколько запросов. Абсолютные цифры мерьте в окружении, близком к боевому.

Панель Twig и время рендера

Панель Twig показывает число отрендеренных шаблонов и время рендера. Тяжёлый рендер обычно означает не медленный Twig, а логику внутри шаблона: вызовы репозитория из {{ }}, фильтры, которые дёргают сервисы, обращения к связанным сущностям (те же ленивые загрузки, просто спрятанные в шаблоне).

Если в панели Twig время большое, а панель Doctrine показала всплеск запросов — почти всегда это данные, которые тянутся во время рендера, а не при подготовке контроллером. Выносите выборку данных в контроллер или в отдельный сервис, в шаблон передавайте готовые структуры.

Когда встроенного профайлера не хватает

Symfony Profiler даёт картину по секциям и по подсистемам (Doctrine, Twig, HTTP-клиент, кеш, события). Чего он не даёт — построчного профиля внутри вашего кода. Если время утекает в собственный алгоритм — сериализацию, обход дерева категорий, преобразование данных — тулбар покажет только, что секция «контроллер» долгая, но не какая функция виновата.

Здесь нужен инструмент, который снимает профиль на уровне вызовов функций:

Практическое разделение: профайлер Symfony отвечает на вопрос «в какой подсистеме проблема», Blackfire и XHProf — «в какой функции». Начинать почти всегда стоит с первого — он бесплатный, уже установлен в dev и в 80% случаев проблема оказывается в числе запросов к БД, а его видно сразу.

Инклюзивное и эксклюзивное время

При чтении дерева вызовов в Blackfire или XHProf различайте два числа. Инклюзивное время функции — вместе со всем, что она вызвала внутри. Эксклюзивное — только её собственный код. Функция с огромным инклюзивным и крошечным эксклюзивным временем сама быстрая — узкое место в её потомках. Оптимизировать надо ту, у которой велико эксклюзивное время, либо ту, что вызывается слишком часто.

Где выводы обманывают

• Первый запрос после деплоя. Холодный кеш конфигурации и метаданных Doctrine даёт цифры в разы хуже стабильных. Мерьте на прогретом кеше, отбрасывайте первый прогон.
• Локальная база быстрее боевой. На локали СУБД рядом, latency почти нулевая. В проде 214 запросов по сети — это 214 умножить на реальный round-trip. N+1, незаметный локально, роняет прод.
• Профилирование меняет то, что мерит. Включённый сбор данных сам добавляет время. Абсолютные значения в dev-тулбаре не переносите в SLA.
• Один запрос — не нагрузка. Профиль одиночного запроса не покажет проблем с блокировками, пулом соединений и памятью под параллельностью. Для этого нужно нагрузочное тестирование, а не профайлер.

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

Порядок действий, который экономит время:

1. Откройте тулбар, посмотрите на панель Doctrine: число запросов против числа различных. Расхождение — ищите N+1.
2. Проверьте панель Twig: тяжёлый рендер почти всегда означает данные, которые тянутся в шаблоне.
3. Убедитесь, что мерите на прогретом кеше и в окружении, близком к prod по latency базы.
4. Если проблема в собственном коде, а не в подсистемах — ставьте Blackfire или XHProf и читайте дерево по эксклюзивному времени.
5. Для выводов о поведении под нагрузкой снимайте не профиль одного запроса, а результаты нагрузочного теста.

Инвалидация и прогрев кеша Doctrine — отдельная тема, здесь мы смотрели только на то, как читать цифры профайлера. Следующий показатель, за которым стоит следить в проде, — не среднее время ответа, а p95 и p99: именно хвост распределения ловит N+1 и промахи кеша, которые среднее сглаживает.