Средства отладки

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

Включение отладчика

Отладчик активируется через URL: к адресу любой страницы нужно добавить GET-параметр debug_on_KEY, где KEY — секретный код, заданный в параметре MELBIS_DEBUG_CODE в конфигурации (или через «Проектирование → Инсталляция», поле «Пароль отладчика»).

Например, если код — pass:

https://site.com/?debug_on_pass
https://site.com/?topic_id=5&debug_on_pass

Состояние отладчика сохраняется в PHP-сессии — после активации он остаётся включённым при любых переходах между страницами сайта. Это позволяет изучать работу разных страниц, не добавляя параметр к каждому URL вручную.

Для отключения — перейти на любую страницу с параметром debug_off:

https://site.com/?debug_off

Машинный вид — debug_ai_KEY. Тот же секретный код, но вместо панели страница получает только отчёт — тем же JSON, который панель даёт по кнопке «Download Reports», в теге <script type="application/json" id="melbis-report-json">. Панель со стилями, таблицами и таймлайном при этом не собирается: это около четырёх пятых её объёма, и читающей программе она не нужна. Режим действует ровно на один запрос и в сессии не сохраняется, поэтому включать и выключать его не нужно. Размеры файловых кешей в этом виде берутся только если их уже посчитала сессия: их подсчёт обходит каталоги кеша, а разового запроса это не стоит.

Метод MELBIS()->DebugState() позволяет в коде модуля проверить, включён ли отладчик, и вывести контрольные данные только в режиме отладки без влияния на продакшн:

if ( MELBIS()->DebugState() )
{
    error_log('Значение переменной: ' . print_r($data, true));
}

Панель отладчика

Строка сводки

В самом верху — краткая сводка текущего запроса:

Три числа у Cache Static нужны потому, что память APCu общая: между «сколько занял ваш проект» и «сколько всего свободно в сегменте» может лежать что-то ещё. Если второе число близко к третьему, APCu начнёт вытеснять записи, и промахиваться мимо кеша начнут даже те запросы, которые вели себя образцово.

Временна́я шкала (Timeline)

Под сводкой — горизонтальная полоса, которая показывает, как распределилось время генерации страницы между всеми модулями. Каждый модуль закрашен несколькими цветовыми полосами в зависимости от способа, которым был обработан:

Наведя курсор на сегмент, можно увидеть имя модуля, время и процент от общего времени страницы.

Таблица «Page Modules»

Детальная статистика по каждому модулю страницы. Колонки:

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

В строке Summary внизу — итоговые суммы по всем модулям страницы.

Таблица «Modules details»

Раздел подробного анализа кеша для каждого модуля (отображается при включённом кешировании). Для каждого модуля показана строка с заголовком: имя, количество отслеживаемых таблиц и количество вызовов на странице.

Для каждого вызова модуля отображается:

Last update — таблица, которая изменялась последней среди всех зависимых таблиц, с указанием времени изменения. Показывает, что именно потенциально могло сбросить кеш. Правее — текущее время сервера (right now), чтобы видеть актуальную разницу.

Cache state — состояние кеша: включён ли, таймаут, временны́е метки последних папок кеша.

Cache load — каким способом получен результат для этого конкретного вызова:

• Run Native — модуль выполнился, кеш создаётся.
• Run Smart — модуль выполнился досрочно по инициативе Smart-кеша.
• Cache Base Valid — кеш актуален, взят с диска. Показывается время создания кеша и таблица, определившая его актуальность.
• Cache Base Pause — кеш актуален по паузе. Видны время создания кеша, время до конца паузы (ETA) и дедлайн.
• Cache Trick — отдан Trick-кеш. Указывается причина: превышение нагрузки (High Server load) или времени компиляции (Long Page compile), фактическое и допустимое значения, возраст Trick-кеша.

Run info — тайминг конкретного вызова: время начала (Start), конца (End), длительность (Run) и доля в общем времени страницы (Part). Ниже — входные параметры, с которыми был вызван модуль.

Таблица «Cache Smart Monitor»

Накопительная статистика работы кеша за всё время наблюдения (хранится в APCu). Показывается если у хотя бы одного модуля включён Smart-кеш. Именно эти данные Smart-кеш использует для принятия решений о досрочном обновлении.

Для каждого модуля — строка с его настройками кеша и семь колонок статистики в формате Cnt/Sum/Avg (количество / суммарно / среднее):

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

Кнопка «Сброс Smart-данных модуля» в IDE очищает накопленную статистику конкретного модуля.

Таблица «Static Cache»

Разбор кеша отдельных SQL-запросов (SqlSelectStatic, SqlSelectStaticFlat). Записи группируются по тексту запроса: одна строка — один SQL, независимо от того, с какими параметрами его вызывали. Сортировка по занимаемому объёму, самые тяжёлые сверху.

Как читать среднее и медиану

Это главная пара чисел таблицы, и смотреть надо именно на расхождение между ними.

24 : 18 — числа рядом, попадания размазаны по вариантам равномерно, кеш работает как задумано.

5 : 1 — среднее нарисовано горсткой «горячих» вариантов, а типичная запись отработала ровно один раз. Именно так выглядит ситуация, когда запрос закешировали с чересчур разнообразными параметрами: суммарные попадания набегают за счёт количества, а большинство записей просто занимает память. Одно среднее этого не покажет — оно будет выглядеть прилично.

Сколько при этом тратится памяти, отвечает колонка Unused, %.

Вердикты

Проверки идут в этом порядке, и Good по сэкономленному времени намеренно стоит выше частотных: тяжёлый запрос, вызванный десять раз, разгружает сервер сильнее, чем лёгкий, вызванный тысячу раз, и получить за это Poor он не должен.

Отчёт показывается только при включённом кешировании (MELBIS_CACHE): при выключенном SqlSelectStatic работает как обычный SqlSelect, новых записей не появляется и показывать нечего.

Выгрузка отчёта: кнопка «Download Reports»

Под строкой сводки есть кнопка Download Reports. Она скачивает JSON-файл со всеми исходными данными панели — не картинку и не разметку таблиц, а те самые числа, из которых таблицы построены.

Что внутри:

• env — версия сборки, шаблон, язык, время генерации, память, число подключённых файлов, нагрузка на сервер, счётчики SQL;
• cache — размеры всех уровней кеша и заполненность сегмента APCu;
• units — по каждому модулю вся собранная статистика: вызовы и времена по всем режимам, счётчики запросов, самый долгий запрос с параметрами, флаги кеша и список отслеживаемых таблиц;
• static — по каждой группе статического кеша полный набор метрик, текст запроса и список попаданий по каждой записи — по нему можно посчитать любое распределение, а не только среднее с медианой;
• smart — накопленная статистика Smart-кеша.

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

Разбор с помощью AI

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

Что осмысленно спрашивать:

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

Последний пункт — самый практичный. Скачайте файл до оптимизации и после, отдайте оба: разница по конкретным числам видна куда лучше, чем по ощущениям от скорости страницы.

В выгрузку попадают тексты SQL-запросов, имена модулей и структура таблиц вашего проекта. Это не пароли и не данные покупателей, но и не то, что стоит выкладывать публично, — относитесь к файлу как к внутренней технической информации.

Инструмент: RunTime

Для точечного измерения времени выполнения произвольного участка кода:

// Засечь начало
$start = MELBIS()->RunTime();

// ... код, который нужно измерить ...

// Получить прошедшее время
$elapsed = MELBIS()->RunTime($start);

if ( MELBIS()->DebugState() )
{
    error_log("Расчёт скидок: {$elapsed}s");
}

RunTime() без аргумента возвращает текущую временну́ю метку. RunTime($start) — разницу между текущим временем и $start.

Инструмент: отладка через файловый дамп

При разработке AJAX-модулей и веб-модулей обычная отладка через вывод в браузер не работает — результат уходит в JavaScript и там теряется. В таких случаях удобно сохранить промежуточные данные в файл:

// Сохранить массив $data в файл dump.htm рядом с шаблонами модуля
MELBIS()->TplDumpVar('dump', $data);

Файл создаётся в каталоге шаблонов текущего модуля. После отладки не забудьте удалить вызов.

Практические сценарии

Найти медленный модуль. Посмотреть строку сводки (Compile) и временну́ю шкалу — розовые (Run Native) сегменты с наибольшей шириной указывают на самые долгие выполнения. В таблице «Page Modules» найти строку с максимальным Total Time и изучить Content of query for max time.

Проверить что кеш работает правильно. В таблице «Page Modules» у большинства модулей должны быть ненулевые значения в колонках Cache Base Valid или Cache Base Pause. В «Modules details» для каждого вызова должно стоять Cache Base Valid или Cache Base Pause, а не Run Native.

Понять, почему кеш сбрасывается слишком часто. В «Modules details» смотреть колонку Last update — там видно, какая таблица изменялась последней и в какое время. Если кеш сбрасывается по таблице, которая не должна влиять — возможно, она лишняя в списке зависимостей модуля.

Оценить эффективность Smart-кеша. В «Cache Smart Monitor» соотношение Run Smart к Run Native показывает, насколько Smart-кеш успевает обновлять данные в фоне, не допуская «холодного» запуска при живых посетителях.

Проверить срабатывание Trick-кеша. В таблице «Page Modules» колонка Cache Trick должна быть ненулевой только при реально высокой нагрузке. Если Trick срабатывает постоянно при нормальной нагрузке — нужно пересмотреть пороги в настройках модуля.

Найти запрос, который зря занимает память. В таблице «Static Cache» отсортированы по объёму — смотреть сверху. Тревожное сочетание: большая Share, %, высокий Unused, % и расхождение среднего с медианой в Hit/Var. Это значит, что запрос закеширован со слишком разнообразными параметрами: попаданий вроде много, но приходятся они на горстку вариантов, а остальные записи просто лежат. Движок помечает такую строку вердиктом Bloat.

Понять, стоит ли вообще кешировать запрос. Смотреть Saved — оценку сэкономленного процессорного времени. Дешёвый запрос с тысячей попаданий может экономить меньше, чем тяжёлый с десятком; в первом случае кеш занимает память почти без пользы.

Сравнить состояние до и после правки. Скачать отчёт кнопкой Download Reports перед оптимизацией и после неё, затем отдать оба файла языковой модели с просьбой показать разницу. По числам это видно точнее, чем по субъективному ощущению скорости.