MySQL slow_query_log в Bitrix: как найти тормозящие запросы

Три месяца мы знали: что-то тормозит. LCP каталога — 4.1 секунды. Где проблема — нет.

Мы смотрели в PHP-профилировщик. Он показывал «время выполнения запроса» суммарно — 280 ms на страницу. Нормально. Мы переписали пару тяжёлых функций. Не помогло. Проверили opcache — всё включено. Добавили CDN для статики. LCP стал 3.8 секунды. Лучше, но не там.

В итоге помогла одна строка в my.cnf, которая была доступна всё это время.

Почему PHP-профилировщик не видел

PHP-профилировщик (xDebug, Blackfire, Tideways) измеряет время внутри PHP-процесса. Он видит, что CIBlockElement::GetList работает 280 ms. Но он не видит, что из этих 280 ms — 240 ms это ожидание ответа от MySQL. Одно число. Без разбивки.

Если узкое место в базе данных, а не в PHP, профилировщик покажет симптом, а не причину. Мы три месяца лечили симптом.

slow_query_log: одна строка, которую не добавляют без повода

В my.cnf (или /etc/mysql/mysql.conf.d/mysqld.cnf в зависимости от дистрибутива):

slow_query_log = 1
slow_query_log_file = /var/log/mysql/slow.log
long_query_time = 1
log_queries_not_using_indexes = 1

long_query_time = 1 — логировать всё дольше 1 секунды. На нагруженном проде можно поставить 2, чтобы не перегружать диск. log_queries_not_using_indexes = 1 — логировать и быстрые запросы без индексов: это полезно отдельно.

Перезапуск не нужен — SET GLOBAL slow_query_log = 1 работает на лету. Мы включили на ночь и утром прочитали лог.

На диске за 8 часов — 340 MB файл. Это нормально для нагруженного каталога.

Что мы увидели в логе

Сырой slow log читать неудобно. Я использовал pt-query-digest из Percona Toolkit:

pt-query-digest /var/log/mysql/slow.log > digest.txt

Инструмент группирует похожие запросы, считает суммарное время выполнения за период и выдаёт рейтинг. В нашем случае топ-14 запросов занимали 94% суммарного времени медленных запросов.

Первый в рейтинге выполнялся в среднем 3.2 секунды. За ночь — 4800 раз. Итого: 4.3 часа MySQL ждал только этот запрос.

Сам запрос выглядел примерно так:

SELECT BE.ID, BE.NAME, ...
FROM b_iblock_element BE
LEFT JOIN b_iblock_element_property EP1 ON EP1.IBLOCK_ELEMENT_ID = BE.ID AND EP1.IBLOCK_PROPERTY_ID = 113
LEFT JOIN b_iblock_element_property EP2 ON EP2.IBLOCK_ELEMENT_ID = BE.ID AND EP2.IBLOCK_PROPERTY_ID = 117
LEFT JOIN b_iblock_element_property EP3 ON EP3.IBLOCK_ELEMENT_ID = BE.ID AND EP3.IBLOCK_PROPERTY_ID = 122
WHERE EP1.VALUE = 'Y' AND EP2.VALUE = '48' AND EP3.VALUE LIKE '%красный%'
ORDER BY BE.SORT
LIMIT 40 OFFSET 0

Три JOIN к b_iblock_element_property — по одному на каждое свойство в фильтре. На каталоге в 28k SKU с двумя тысячами пользователей в час это работало плохо.

Как Bitrix D7 ORM генерирует это

Вот откуда берётся такой запрос. В коде это выглядело безобидно:

$result = \Bitrix\Iblock\ElementTable::getList([
    'filter' => [
        '=PROPERTY_IN_STOCK.VALUE' => 'Y',
        '=PROPERTY_SIZE.VALUE' => '48',
        '%=PROPERTY_COLOR.VALUE' => 'красный',
    ],
    'select' => ['ID', 'NAME', 'IBLOCK_SECTION_ID'],
    'order' => ['SORT' => 'ASC'],
    'limit' => 40,
]);

Три свойства в фильтре → три JOIN к b_iblock_element_property. Фильтр по LIKE '%красный%' с ведущим % делает индекс бесполезным — MySQL читает всю таблицу с JOIN-ами.

Не баг Bitrix. Просто так работает EAV-таблица хранения свойств. В slow log это видно сразу. В PHP-профилировщике — нет.

Паттерны, которые медленные всегда

За неделю работы с digest-файлом мы нашли несколько повторяющихся проблем.

Самая частая — LIKE '%слово%' в PROPERTY_* поле. Ведущий процент делает индекс бесполезным: MySQL читает всю таблицу с JOIN-ами. На нашем каталоге это был один медленный запрос на каждую страницу фильтра. Мы перенесли фильтрацию по тексту на Elasticsearch — он уже был для поиска.

ORDER BY по SORT без составного индекса — отдельная история. getList сортировал 28k строк полностью, потом отдавал 40. Исправление заняло 20 минут: миграция с индексом (IBLOCK_ID, SORT, ID), без изменений в коде.

Ещё один паттерн — N+1, спрятанный в ORM. getList возвращает 40 элементов, потом в цикле для каждого отдельный GetProperty. В slow log это выглядит как 40+ одинаковых запросов по 50-80ms каждый. В сумме — 2-3 секунды. Решение: добавить нужные свойства в select основного запроса.

Что мы изменили и что измерили

На исправление трёх проблем ушло три дня.

Запрос с PROPERTY JOIN-ами: перенесли «in stock» и «size» в отдельную таблицу через high-load properties, LIKE '%красный%' убрали через Elasticsearch. Время запроса: 3.2s → 0.18s.

Сортировка: добавили составной индекс (IBLOCK_ID, SORT, ID). Код не трогали, только миграция. Время: 1.8s → 0.09s.

N+1 в карточке товара: было 47 запросов, стало 8. PHP время: 680ms → 190ms.

LCP каталога через неделю: 4.1s → 1.9s. CDN и картинки — это отдельная история.

Что не сработало

pt-query-digest хорошо группирует однотипные запросы, но иногда паттерны разные по форме — и они попадают в разные группы. Два запроса с одной проблемой, но разным набором свойств, он считает разными. Пришлось смотреть не только top-14, но и дальше по списку.

Ещё — log_queries_not_using_indexes = 1 включил много шума от служебных Bitrix-запросов. Пришлось фильтровать по базе (use_db) и исключать b_agent, b_option, b_session. В pt-query-digest есть --filter для этого.

Итог

Три месяца, PHP-профилировщик, четыре гипотезы. Потом один день slow_query_log.

На маленьком проекте он не нужен. Но если LCP не падает, профилировщик показывает «всё нормально», а пользователи жалуются — смотрите в базу, а не в PHP.

Про то, что ещё можно сделать на уровне PHP до того, как смотреть в MySQL — написал отдельно в PHP OPcache и Bitrix. А про общие паттерны, которые делают Bitrix медленным независимо от базы — в Bitrix не тормозит.