Профилирование Битрикс: как найти медленный код на странице

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

Что нужно знать до замеров

Материал написан для «1С-Битрикс: Управление сайтом» на ядре D7, PHP 8.x и Xdebug 3.x. Названия пунктов админки отличаются в зависимости от редакции и версии модуля main, поэтому ищите их по смыслу.

Перед профилированием определите три вещи:

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

Четыре подхода и их цена

Панель «Отладка»

В публичной части в административной панели есть кнопка «Отладка». Она включает вывод времени страницы и компонентов, статистики SQL-запросов и кеша. Режим привязан к вашему сеансу, посетители ничего не видят. Выигрыш: не нужно ничего устанавливать, сразу видно, какой компонент тяжёлый и сколько у него запросов. Цена: код из init.php и обработчиков событий остаётся в серой зоне.

Монитор производительности (Perfmon)

Модуль perfmon ведёт журнал хитов, SQL-запросов и обращений к кешу, а ещё подсказывает индексы. Раздел ищите в «Настройки → Производительность». Выигрыш: статистика по всему сайту, а не по одному заходу, и список самых долгих запросов. Цена: модуль сам пишет в базу, поэтому на нагруженном проде его включают на короткое окно.

Метки и SqlTracker в коде

Если подозреваете конкретный участок, оберните его метками времени и трекером запросов из D7. Выигрыш: точность, вы мерите ровно свой код и видите SQL с временем каждого запроса. Цена: правка кода, которую потом нужно убрать.

Xdebug в режиме профилировщика

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

Метки и трекер на практике

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

<?php
use Bitrix\Main\Application;
use Bitrix\Main\Diag\Debug;

$connection = Application::getConnection();
$connection->startTracker();
Debug::startTimeLabel('catalog_block');

// участок, который подозреваете

Debug::endTimeLabel('catalog_block');
$connection->stopTracker();

$lines = [];
foreach ($connection->getTracker()->getQueries() as $query) {
    // время запроса в секундах и его текст
    $lines[] = round($query->getTime(), 4) . ' ' . $query->getSql();
}

// путь указан от корня сайта
Debug::writeToFile($lines, 'sql', '/local/logs/profile.log');
Debug::writeToFile(Debug::getTimeLabels(), 'labels', '/local/logs/profile.log');

Имена методов проверьте в своей версии ядра: исходники лежат в /bitrix/modules/main/lib/diag/, описание есть в документации D7. Лог не должен открываться из браузера. Закройте каталог правилом веб-сервера и удалите файл после замеров.

Что находят чаще всего

• Запросы в цикле. На 20 элементах списка получается 20 лишних обращений к базе.
• Кеш компонента, который не работает: CACHE_TYPE выставлен в N, либо при CACHE_FILTER со значением Y на странице с фильтром кеш дробится на множество ключей.
• Агенты, которые выполняет случайный посетитель. Если их не вынесли на cron, страница периодически тормозит без видимой причины. Перенос описан в документации Битрикса.
• Тяжёлый код в init.php и обработчиках событий: он выполняется на каждом хите.
• Фильтры по свойствам без подходящих индексов. Здесь поможет Perfmon.

Кеш не лечит медленный код. Он прячет его от всех, кроме первого посетителя после сброса.

Пояснение. N+1 — это когда один запрос получает список из N записей, а потом для каждой записи уходит ещё по одному запросу за связанными данными. Итого N+1 обращений к базе вместо одного-двух.

Типичный случай в Битриксе: свойство элемента инфоблока читают отдельным вызовом внутри цикла.

<?php
use Bitrix\Main\Loader;

Loader::includeModule('iblock');

$iblockId = 5; // подставьте ID своего инфоблока
$order = ['SORT' => 'ASC'];
$filter = ['IBLOCK_ID' => $iblockId, 'ACTIVE' => 'Y'];
$nav = ['nPageSize' => 20];

// Было: отдельный запрос за свойством на каждый элемент
$res = CIBlockElement::GetList($order, $filter, false, $nav, ['ID', 'NAME']);
while ($item = $res->GetNext()) {
    $brand = CIBlockElement::GetProperty($iblockId, $item['ID'], ['sort' => 'asc'], ['CODE' => 'BRAND'])->Fetch();
}

// Стало: свойство приходит в том же запросе
$res = CIBlockElement::GetList($order, $filter, false, $nav, ['ID', 'NAME', 'PROPERTY_BRAND']);
while ($item = $res->GetNext()) {
    $brand = $item['PROPERTY_BRAND_VALUE'];
}

Учтите: для множественных свойств такой запрос вернёт по строке на каждое значение, и результат придётся склеивать.

Xdebug на копии сайта

Настройки для Xdebug 3.x. Режим trigger включает профилирование только для запросов с нужным параметром, остальные работают как обычно.

; Xdebug 3.x, только на тестовой копии
xdebug.mode=profile
xdebug.start_with_request=trigger
xdebug.output_dir=/var/tmp/xdebug

Откройте страницу с параметром XDEBUG_PROFILE в адресе, например /catalog/?XDEBUG_PROFILE=1. В каталоге из output_dir появится файл cachegrind.out с номером процесса в имени. Откройте его в QCachegrind или KCachegrind и отсортируйте по собственному времени функций (self), а не по суммарному. Если вверху оказались функции работы с MySQL, значит время уходит в базу: выпишите запросы через SqlTracker и разбирайте их отдельно. Разбор планов запросов — отдельная тема, здесь не рассматриваем.

Когда что выбирать

• Не знаете, какой компонент тормозит: начните с панели «Отладка».
• Тормозит неизвестно где и неизвестно когда: включите Perfmon на короткое окно и смотрите самые долгие запросы.
• Есть подозрительный участок: метки и SqlTracker.
• Компоненты и SQL времени не объясняют: Xdebug на копии.

Идите от дешёвого к дорогому. Часто хватает первых двух шагов.

Что ломается

• Замеры на тёплом кеше. Тяжёлый код сидит в построении кеша и не виден, пока вы не сбросите его.
• Perfmon оставили включённым. База пухнет от журналов, сайт замедляется сам по себе.
• Лог профилирования лежит в открытом каталоге. Из него можно прочитать SQL и пути к файлам.
• Xdebug включён в php.ini на проде без режима trigger. Каждый хит работает медленнее.
• Абсолютные цифры из Xdebug сравнивают с продом. Смотрите на доли времени, а не на секунды.

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

Возьмите три самых долгих места из отчёта, исправьте одно и замерьте снова в тех же условиях: тот же кеш, тот же пользователь, те же данные. Запишите время до и после, иначе через месяц не вспомните, что помогло. Постоянно следить за скоростью на проде удобнее по логам веб-сервера: добавьте в формат access-лога Nginx переменные $request_time и $upstream_response_time и смотрите, как меняются самые медленные URL.