Использование расширенной отладки. Часть 2: Если тормозят некоторые страницы сайта или ругается подд

Бывает так, что весь сайт работает достаточно шустро, а некоторые его страницы – заметно медленнее. Или создали новый сайт, настроили компоненты, виджеты, добавили материалы, а он тормозит. Или страницы сайта стали загружаться через раз, а поддержка хостинга начала ругаться на превышение лимитов процессора/памяти или на слишком «тяжёлые запросы». Как понять, что именно вызывает эти проблемы?
Конечно, можно по очереди отключать компоненты, убирать виджеты и пытаться визуально оценить, насколько быстрее стал работать сайт. Но легче и удобнее разобраться с причинами вышеописанных проблем используя «Расширенную отладку».

Материал в первую очередь рассчитан на пользователей, которые только начинают разбираться в InstantCMS 2. Но также будет полезен как пример использования отладки и для более опытных.


Важно! До анализа отключите кэширование в Админке.

Считаем, что «Класс расширенной отладки» у вас уже установлен и включён. Первое, что нужно сделать – убедиться, что проблема именно в движке сайта, а не в серверах хостинга. Как это сделать, я описал в "Использование расширенной отладки. Часть 1: Определение проблем на сервере".

Во-вторых, дополнительно можно посмотреть более подробную информацию для разных ситуаций. Нужно понять, тормозят все страницы или только некоторые. Это легко увидеть по цифре "script time" – время работы скрипта. Если на разных страницах она отличается не сильно и везде большая, значит тормозят все страницы. Если большие цифры только на отдельных страницах, значит проблемы именно на них.


Рисунок 1. Основная таблица отладки.
(Картинки некликабельны, но их можно открыть в новой вкладке чтобы посмотреть в реальном размере)

Небольшое отступление. Что значит «большое» время "script time"? Какое оно должно быть? Это зависит от сервера и активных компонентов на странице. На новых шустрых серверах с SSD время создания главной страницы только что установленного демо-Инстанта может быть меньше 100 мс. На серверах помедленнее или на виртуальных с ограничением частоты процессора, а также на системах с большим количеством компонентов/виджетов и данных, время будет в разы больше. Но в любом случае для Instant CMS 2 время генерации страницы должно быть до 500 мс.
Также нужно понимать, что большинство веб-серверов имеют кэширование разного типа. Поэтому нужно смотреть и на цифры при первом открытии страницы, и на цифры после нескольких подряд её обновлений.

Тормозят только некоторые страницы сайта

Тогда на тормозящей странице смотрим время хуков, виджетов, контроллера и рендеринга страницы (на рисунке 1 выделены красной рамкой). И сравниваем их с временем на страницах с нормальной скоростью. На этом рисунке показано примерное соотношение времени в процентах для этих компонентов. На разных страницах и серверах цифры будут отличаться. Но соотношения будут примерно такими же.

widgets – суммарная информация об активных на данной странице виджетах. На большинстве сайтов на страницы будет установлено много вижетов, а значит и время работы виджетов будет велико.

events/hooks – суммарная информация о системных событиях (эвентах) и их обработках (хуках). Во время работы системы происходят разные события. Например, создаются разные меню, запрашивается информация о текущем пользователе, готовится к выдаче контент, проверяются новые сообщения и т.п. Каждое такое событие может быть дополнительно обработано любым компонентом. Например, при получении сообщения можно подать звуковой сигнал. Или при входе пользователя показать ему какое-то сообщение. Или обработать контент типографом. Эти обработки событий требуют времени. В таблице выводится суммарное время всех сработавших хуков.

controller – информация о работе контроллера. Контроллер в InstantCMS 2 – это та часть движка, которая обрабатывает данные (контент). Например, на страницах со статьями это контроллер "content", с фотографиями – "photos" и т.д.

rendering – информация о времени вывода подготовленной контроллером информации в шаблон, а также объём памяти, использованной при этом.

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

Пример 1. Виджеты

Например, на моём домашнем компе виджеты на странице «О проекте» работают примерно 75 мс. Как и на других страницах контента типа pages. А виджеты на «Главной» — 182 мс. Разница значительная. При этом на первой странице активны 6 виджетов (widgets: — count), а на «Главной» — 17 виджетов. Посмотрим, какие виджеты «тяжелее» всех на этих страницах.

Всё просто. Заходим в «Админка – Настройки – Отладка – Виджеты» и ставим галку «Показывать виджеты». Для удобства можно задать значение в «Глубина трассировки для виджетов», так как нам сейчас не нужна трассировка. Нажимаем "Сохранить", обновляем страницу «О проекте» и смотрим внизу под основной таблицей отладки список виджетов и подробный лог.


Рисунок 2. Список виджетов на странице «О проекте».

В списке мы видим 6 виджетов. Которые совпадают с заданными в Админке для всех страниц, что неудивительно. 😊
Верхняя небольшая таблица позволяет с первого взгляда оценить скорость виджетов по колонке «Time avg, ms». Сразу видно, что виджет 'users — avatar' – самый «тяжёлый».
Ту же картину, только подробнее и, отчасти более наглядно видно и в логе виджетов ниже этой таблицы. Виджет «Widget 4 'users — avatar'» работает 41.9 мс. Это «тяжёлый» виджет, выполняющийся более 15 мс (порог времени настраивается в Админке) и поэтому он выделен в списке жёлтым фоном (оформление выделенного настраивается в css, так что при желании вы сможете его поменять под себя). Также жёлтым фоном выделен ещё один виджет «Widget 6 'menu'» — 17.3 мс.

Widget 4 'users — avatar' — 41.9 ms — [ 9 sql: 3.1 ms ][ 22 incl: 11.9 ms ][ +1197 KB (peak) ]

Тут же, кстати, видно, что виджет «Widget 4 'users — avatar'» использовал больше всех памяти — более мегабайта (значение “+1197 KB” в логе). Возможно это из-за того, что он подключил 22 файла. При этом потратил на их подключение почти 12 мс (22 incl: 11.9 ms).
Зато в этой же строке мы видим, что он сделал 9 sql-запросов за 3.1 мс, что очень даже быстро.

Ссылка на рисунок 3. Список виджетов на странице «Главная»

На «Главной» виджетов больше. Из интересного можно заметить, что на ней виджет 'users — avatar' работает ещё дольше – 45 мс – и использует памяти уже 2 мегабайта. Учитывая, что весь скрипт использует 7.7 мегабайт, то 2 мегабайта из них только на один виджет – многовато. Это реально самый тяжёлый виджет в системе. Причём имеющийся, фактически, на любой странице. Может быть это оправдано, я не проверял. А может быть разработчики в своё время оптимизируют и этот виджет тоже.

Второй по «медленности» виджет — 'content — slider', как это ни странно. Он работает 27 мс. Виджет красивый, полезный, но занимает 12% от времени работы всего скрипта. Стоит ли его оставлять на посещаемых сайтах? Вам решать.

Таким образом, сделав несколько щелчков мышкой, вы сразу поймёте, какие виджеты тормозят ваш сайт. Или какие «съедают» неприлично много памяти. И сможете обратиться к разработчику этого виджета с просьбой оптимизировать его работу. R2, Fuse, оптимизируйте виджет 'users — avatar', пожалуйста! 😊))

Пример 2. Хуки

Посмотрим на основную таблицу отладки на странице «О проекте». Время работы хуков около 27 мс. При этом происходит 14 событий, которые обрабатываются 9 хуками. (Нужно понимать, что не все события обязательно должны быть обработаны хуками. И каждое событие может быть обработано несколькими хуками). В принципе, 27 мс – это немного. Но всё же из интереса посмотрим подробнее.

Заходим в «Админка – Настройки – Отладка – События и хуки» и ставим галку «Показывать события и хуки». Также выставляем значение в «Глубина трассировки для виджетов». Показ виджетов, включённый в предыдущем примере выключаем. Сохраняем настройки, обновляем страницу «О проекте» и смотрим список хуков и подробный лог.

Ссылка на рисунок 4. Список событий и хуков на странице «Главная»

В таблице со списком хуков ничего «военного» не наблюдается. Но при просмотре лога евентов и хуков в глаза бросается одна строка, выделенная жёлтым фоном. (В настройках отладки стоит выделять «тяжёлые» хуки длительностью более 5 мс – вы можете это изменить в Админке)

Hook 6 'menu_content — content' — 12.9 ms — [ 1 sql: 0.1 ms ][ 1 incl: 0.3 ms ][ +68 KB (peak) ]

Произошло событие 'menu_content' (его видно выше — «Event 10 'menu_content'»). Оно было обработано контроллером 'content' за 12.9 мс. Во время работы были быстро выполнены по одному sql-запросу (0.1 мс) и подключению файла (0.3 мс). Значит SQL-сервер и дисковая подсистема не тормозят, а хук в это время что-то считал.

Поскольку в данном примере, как и на всём сайте, хуки работают достаточно шустро, то всё в порядке, мы просто нашли самый медленный хук на этой странице. Но если бы время работы этого хука было слишком велико, к примеру, 120 мс, то нужно было бы обратиться к разработчику контроллера 'content' за оптимизацией работы этого хука. То есть, бить тревогу нужно, если какой-то хук сильно выделяется из всех остальных длительным временем работы или большой используемой памятью.

Не побоюсь выглядеть пафосным, но хуки – это будущее InstantCMS 2. Разработчики заложили в систему прекрасную идею: для расширения или изменения функционала системы. Сторонним разработчикам в идеале не нужно менять ядро. В большинстве случаев можно перехватывать события системы и обрабатывая их делать с данными и выводом на страницу всё, что нужно. А недостающие хуки разработчики Инстанта постепенно добавляют по мере пожелания пользователей. Так что чем дальше, тем более важно знать время работы и другую информацию о работе хуков на ваших сайтах и иметь возможность быстро выявить проблемные хуки.

Пример 3. Контроллер

Как я уже говорил, контроллер подготавливает контент определённого типа к выводу в шаблон. На «Главной» странице контента нет, поэтому никакой контроллер не запускается. Это видно и по времени контроллера в основной таблице отладки – около 2 мс на проверку необходимости загрузки контроллера. На странице «О проекте» контроллер работает почти 37 мс, судя по времени «controller: — time» в красной рамочке на рис.1. А вот на странице объявления контроллер «board» работает уже 58 мс.

Если вы установили в систему новый компонент и его страницы загружаются медленнее других, то в первую очередь посмотрите время работы контроллера. Возможно оно слишком большое. Тогда нужно сравнивать другие значения в основной таблице (количество инклудов, sql-запросов) на страницах этого контроллера и более быстрых страницах. И если эти значения на проблемных страницах намного выше, чем на других, то нужно обращаться к разработчику компонента. Возможно в следующих версиях «Расширенной отладки» я сделаю отдельный подсчёт инклудов и запросов для контроллера и рендеринга, чтобы можно было видеть картину точнее.

Пример 4. Рендеринг

Представим ситуацию. Вы создаёте новый сайт. Заказали для него красивую навороченную тему, накачали или купили нужные компоненты, заполнили интересными материалами. Выложили на сервер, а сайт тормозит.
Или добавили на существующий сайт новый компонент, натянули на него свою тему. Везде всё работает быстро, а страницы этого компонента открываются с задержками.

Посмотрите на цифру «rendering: — time» – не слишком ли она высока. На моём домашнем компе рендеринг (сборка, отрисовка) страницы на стандартном шаблоне занимает менее 2-8 мс в зависимости от компонента. На нормальном сервере будет ещё быстрее. Если цифра исчисляется десятками или даже сотнями мс, значит с шаблоном компонента что-то не так. Конечно, так сильно напортачить в шаблоне – это нужно постараться. Но богата наша земля и такими удивительными «мастерами». Так что в подобном случае пишите письма создателю вашего шаблона с просьбой проверить, откуда идут тормоза.

Пример 5. SQL

Предположим, вы нашли в логах хук или виджет с большим временем работы. Что ещё можно узнать? Посмотрите в строке этого хука/виджета на количество и время sql-запросов. Если среднее время одного запроса превышает 1 мс, то есть смыл посмотреть список всех sql-запросов на этой странице.

Это можно сделать и в стандартной отладке, щёлкнув по количеству запросов в подвале страницы, и в расширенной отладке. Разница в большей наглядности и информативности вывода. В расширенной отладке время выводится в наглядных миллисекундах, а не в неудобных дробных секундах, текст запроса выводится в отдельном блоке. Есть трассировка вызова на любое количество уровней, а не только вывод строки вызова, то есть можно точнее и быстрее понять, откуда растут ноги у конкретного запроса. Также выводится результат запроса или сообщение об ошибках в случае неудачи. Дополнительно есть подсветка «тяжёлых» запросов, что сразу выделяет их на фоне остальных. Как и для других логов в отладке, порог срабатывания подсветки задаётся в Админке в мс. И есть фильтры по строке запроса и/или по вызвавшему его файлу, которые позволяют, например, отфильтровать только запросы из нужного компонента или к интересующей таблице.

Итак, смотрим список запросов к БД для «Главной».
Ссылка на рисунок 5. Начальная часть списка запросов к БД для «Главной»

Все запросы выполняются быстрее, чем за 1 мс. И только один выделен жёлтым фоном, так как выполнялся больше 3 мс, а в Админке задан порог для выделения «тяжёлых» запросов в 3 мс. На самом деле и это довольно быстро для запроса такого типа. Я его привёл только как пример. У вас время может быть намного бОльшим.
Недавно мне прислали для анализа лог запросов на выборку, которые выполнялись больше одной секунды (более 1000 мс). Это реальные тормоза. И конечно, поддержка хостинга тоже была недовольна такими «тяжёлыми» запросами.


Рисунок 6. «Тяжёлый» sql-запрос

Что можно тут увидеть. Конечно сразу виден текст самого запроса. Это запрос на добавление данных INSERT INTO, который к тому же в некоторых случаях выполняет два подзапроса. Как раз в этом случае было именно так. И в значении «Affected/returned rows» (обработанные строки) видно, что обработано две строки.

Далее, по трассировке вызова (список «лесенкой» под текстом запроса) можно понять, какая часть скрипта выполняет этот запрос. В данном случае вызов идёт из класса User ядра в файле /system/core/user.php. В случае, если запрос выполняется из компонента, в трассировке будет файл с путём типа /system/controllers/имя_контроллера/имя_файла.php. Зная имя контроллера можно понять какой компонент вызывает проблему и к какому разработчику обращаться.

По-умолчанию в настройках для всех трассировок отладки задан уровень 3. Обычно этого хватает. При необходимости можно для любого вида логов либо убрать трассировку вообще, либо увеличить количество уровней до 20 с шагом 1, чего хватит с головой для любых задач.

Пример 6. Память

Потребление памяти у такого навороченного движка, как InstantCMS 2, должно было быть большим. Но благодаря очень грамотной организации внутренней структуры и качественному кодингу разработчики добились довольно экономного использования. Например, для «Главной» с кучей виджетов для залогиненного пользователя мы на рис.1 видим пик памяти «memory: — peak» 7.355 MB. Для разных страниц пик памяти в основном колеблется в пределах 6.5-7.5 MB, иногда немного выходя за эти границы.

Если компонент написан без учёта использованной памяти, то цифра пика может вырасти значительно выше. Увидеть, что именно сильно потребляет память, можно сравнив цифры «memory» разных частей скрипта у страниц со стандартными компонентами и со сторонними. А подробности можно посмотреть в логах, как мы это делали для виджетов.

Пара моментов про память. Первый, это то, что память на сервере выделяется поблочно, а не побайтно. Например, блоками по 256 KB (0.25 MB). То есть, для той же «Главной» 7.355 MB точной памяти на самом деле являются 7.5 MB выделенной памяти. В «Расширенной отладке» можно включить галку «Показывать полное (блочное) выделение памяти скрипту» и получить реальные цифры выделения памяти скрипту сервером.

Второй момент в том, что стандартная отладка показывает объём памяти на момент окончания скрипта. Что неверно. Так как в большинстве случаев к этому момент часть памяти освобождается и цифра получается уже несколько ниже максимальной. Например, для «Главной» пиковое потребление 7.355 MB, а на момент окончания скрипта – 6.97 MB.

Почему цифры памяти так важны? Для PHP на сервере выделяется определённое количество памяти. Например, на недорогих хостингах это может быть 256 MB, а иногда и меньше. При использовании до 8 MB для создания каждой страницы, можно одновременно создавать до 32 страниц. (Другой вопрос, потянет ли такое число страниц процессор или дисковая подсистема, но мы его сейчас не рассматриваем). Если в систему установлен «тяжёлый» компонент, неправильно работающий с памятью, да ещё и очень долго, то количество одновременно генерируемых страниц падает, а запросы на страницы, для которых не хватило памяти, будут отвергнуты. Вместо этих страниц пользователи получат сообщения об ошибке сервера, а в логах сервера будут сообщения о превышении лимита памяти. То есть, у пользователей периодически перестанут открываться страницы сайта. Причём совершенно разные, а не только страницы этого «тяжёлого» компонента. Поэтому для посещаемых сайтов важно знать реальное потребление памяти движком и правильно выбирать тарифный план на хостинге с подходящим объёмом памяти. Для расчётов нужно учитывать полное (блочное) пиковое выделение памяти. А создателям компонентов нужно заботиться о правильной работе с памятью и своевременно её освобождать.

В следующей части этой темы я постараюсь показать, как можно легко и наглядно наблюдать за расходом памяти (а также за другими параметрами) своих компонентов при их написании и проверке.

Тормозят все страницы сайта

Если вы уверены, что с сервером всё в порядке (прочитали и применили «Часть 1» этой темы), тогда причины тормозов могут быть связаны с движком. Просмотрите все значения времени, о которых я писал выше. Вероятнее всего какие-то из них будут высокими и при этом повторяться на всех страницах. Как только найдёте их, дальнейшие действия будет такие же, как и в случае, когда тормозят не все страницы. Например, это может быть какой-то виджет, установленный на все страницы. Или сторонний компонент, добавивший свой «тяжёлый» хук на какое-то событие, возникающее на всех страницах. Тогда тормоза тоже будут на всех страницах сайта, а не только на страницах этого компонента. В-общем, технология поиска аналогична вышеописанной.

В заключение этой части

После определения вероятной причины, нужно попробовать убедиться в её правильности. Для виджетов это сделать легко – просто временно убрать проблемный виджет со страницы и сравнить время работы скрипта «script time» с ним и без него. Для тем можно временно переключиться на дефолтную тему. С хуками и компонентами тяжелее. Пока нет стандартного способа их отключения в Админке. В базе данных движка такая возможность заложена, но в скриптах пока не реализована. Так что тут поможет только общение с разработчиком или какие-то нестандартные ухищрения. Например, хук можно временно отключить, удалив его из манифеста компонента или закомментировав его там. Главное предварительно сделать копию этого манифеста и не оставлять так систему дольше, чем вам нужно для проверки времени.

Надеюсь, вам была полезна эта информация. Теперь вы немного лучше понимаете работу этой прекрасной CMS и с помощью «Расширенной отладки» сможете самостоятельно найти причины наиболее частых проблем, а иногда и устранить их на сайте до исправления проблемного компонента.


P.S. Обратите внимание! Приведённые мной цифры и диапазоны взяты из моего опыта и подходят для моего компьютера и хостинга. Ваши цифры будут отличаться. Обращайте внимание больше на соотношения цифр, а не на их значение. Но всё же, если на вашем хостинге цифры намного выше приведённых мной, то подумайте о том, чтобы перейти на другой тарифный план или сменить хостинг.