Использование расширенной отладки. Часть 3. Изучаем работу InstantCMS 2 без знания PHP

+36
3.14K
Использование расширенной отладки. Часть 3. Изучаем работу InstantCMS 2 без знания PHP

При создании своих сайтов любой вебмастер довольно быстро сталкивается с необходимостью хотя бы в общих чертах понимать, как устроена и работает выбранная им CMS. Попробуем наглядно посмотреть, как работает InstantCMS 2, без знания программирования и без чтения php-кода системы на примере одной из страниц демо-сайта. Это очень просто!

Иллюстрация

Сначала немного теории – куда без неё. В документации на странице Введения для разработчиков описана схема работы системы. Процитирую её сюда для наглядности. Она последовательная и простая.

1. Запускается файл index.php;
2. Роутер определяет какой компонент был запрошен и запускает его контроллер;
3. Контроллер получает параметры запроса из URL, либо из формы заполненной пользователем;
4. Контроллер получает (или сохраняет) данные через модель;
5. Контроллер обрабатывает данные необходимым образом;
6. Контроллер вызывает шаблон и передает в него полученные (или обработанные) данные;
7. Шаблон формирует конечную HTML-страницу, которая возвращается пользователю.

Попробуем увидеть эту схему прямо на работающем демо Двойки. Например, посмотрим, что происходит при открытии страницы «О проекте» по адресу тестовый_сайт/pages/about.html на домашнем локальном сервере.

В настройках Админки включаем расширенную отладку. Включаем показ событий и хуков на вкладке «События и хуки» — «Показывать события и хуки». Изменяем значение «Глубина трассировки для хуков» на , чтобы не выводить ненужную нам пока информацию. Ставим галки на вкладке «Другое» — «Показывать в логе вызов контроллера», «Показывать в логе инициализацию шаблона» и «Показывать в логе вызов рендеринга шаблона». Сохраняем конфигурацию и открываем страницу «О проекте».

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

Рисунок 1. Лог событий, хуков и виджетов.

На скриншоте видны строки нескольких типов строк лога, выделенные разными цветами. Кратко их опишу:

Event – событие, произошедшее в системе
Hook – обработка произошедшего события каким-то контроллером.
В документации для разработчиков подробно рассказано про события и их обработку. Если вы знаете PHP, то прочитайте, если нет, то пока пропустите.
Controller – работа контроллера, обрабатывающего определённый тип контента или выполняющего иные функции в системе. В логе фиксируются моменты начала работы контроллера (start) и окончания (end). Тут Документация по контроллерам
Template init – инициализация шаблона. Во время инициализации шаблона происходит определение его имени, если оно не задано, выполняется загрузка опций шаблона и некоторые другие начальные действия с шаблоном (start и end).
Rendering – рендеринг (сборка, заполнение данными) шаблона шаблоном (start и end).

Смотрим лог

Строки в логе идут в том порядке, в котором они происходят в системе при создании страницы. Значит сначала смотрим на первую строку:

Template init 1 start — [ 20 ms ] /index.php (35) cmsTemplate::getInstance


Мы видим, что первым после всех стартовых действий CMS происходит загрузка и инициализация шаблона. На момент старта инициализации ещё неизвестно имя шаблона, поэтому оно тут не показывается.

В квадратных скобках выводится время в миллисекундах, прошедшее с момента старта скрипта (при наведении мышки на цифру появится подсказка о том, что это такое). Оно может быть полезно, например, для быстрой оценки времени между разными логируемыми событиями. В данном примере с момента старта скрипта прошло 20 мс. По опыту могу сказать, что примерно 5 мс заняла загрузка отладки и запуск сессии (если отладка отключена, то это время уменьшится до 1 мс и меньше). И ещё около 15 мс занимает загрузка конфигурации сайта, основных классов и библиотек, старт кєша, подключение к БД.

Также мы можем видеть, в какой именно строке какого файла произошёл вызов этого события – строка 35 файла /index.php. В дальнейшем я опущу информацию о месте вызова, так как мы сейчас рассматриваем работу системы без применения знаний PHP.

Template init 1 'default' end — 5.7 ms — [ 25.8 ms ][ 0 sql: 0 ms ][ 8 incl: 4.4 ms ][ 0 events: 0 hooks: 0 ms ][ +827 KB (peak) ]


Инициализация шаблона 'default' завершена за 5.7 мс через 25.8 мс после начала старта скрипта. К этому моменту же известно имя шаблона и оно выведено в лог. Также видно, что SQL-запросов к БД, а также событий и хуков не было. Зато за 4.4 мс были подключены 8 php-файлов (по прямой загрузке или в автозагрузке классов).

Инициализация шаблона «съела» 827 килобайт памяти, то есть, память по сравнению с началом инициализации увеличилась на эту цифру. На самом деле в это время подгружались и другие классы ядра, поэтому 827 – это не только память на шаблон, но и на эти классы. Изменение памяти выполняется по пиковому значению – примечание «(peak)» в логе. Подробнее про методы расчёта памяти смотрите в документации к отладке.

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

Далее я не буду уделять внимание параметрам в логе, вы их можете сами посмотреть в моём примере лога или на своих сайтах. Пройдёмся по дальнейшим событиям в системе.

Event 1 'engine_start'


Это первое событие (event), произошедшее в системе. Жирным шрифтом выделено внутреннее название этого события – 'engine_start'. Из него следует, что произошёл старт движка CMS. Поскольку после этого события нет строк с хуками, значит это событие на данной странице в данной конфигурации компонентов ничем не обрабатывается.

В этом месте должна быть ваша реклама должен быть запуск роутинга. Но роутинг занимает очень короткое время, несколько мс, не совершает обращений к файлам и БД, не имеет событий и хуков, не зависит от сторонних компонентов и тем. Поэтому отладка его отдельно не регистрирует.

Controller 1 start


Пытаемся запустить контроллер. Мы ещё не знаем, какой именно контроллер будет обрабатывать страницу, так как определение этого происходит в начале функции запуска контроллера. Если для адреса текущей страницы нет обрабатывающего контроллера (например, у главной страницы в демо), то после выяснения этого факта происходит завершение работы функции запуска контроллера. Если контроллер есть, то он включается в работу и подготавливает данные для страницы. Но согласно концепции MVC, по которой построен InstantCMS 2, он пока не выводит их в шаблон, а сохраняет в своей памяти.

В логе мы видим, что в период работы контроллера происходят следующие события.

Event 2 'user_loaded'


Произошла загрузка пользовательских данных для залогиненного пользователя. Это событие уже обрабатывается хуком (следующая строка в логе):

Hook 1 'user_loadedusers'


Ярко-красным цветом в логе выделяются события, более тёмным – хуки. Если подвести мышку к любой из частей названия 'user_loadedusers', то появится подсказка, что это такое. Например, для 'users' подсказка будет «Controller». Значит событие 'user_loaded' обрабатывается хуком контроллера 'users', что, в-принципе, логично.

Далее идут три похожих события:

Event 3 'content_before_item'
Event 4 'content_pages_before_item'
Event 5 'content_pages_item_html'


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

Второе событие – то же самое, но происходит не для любого контента, а только для контента типа «pages». Это позволяет написать специализированный обработчик, который будет что-то менять только на страницах с типом «pages». Это как раз тот тип страниц, который мы сейчас изучаем. Для фотографий, например, это событие будет называться 'content_photos_before_item'.

Третье событие позволяет обработать уже готовый html-текст контента. Обращаю внимание, это не текст страницы целиком, а только html-версия контента для вывода в тело страницы (статья, объявление, оформленная фотография и т.п.).

Мы видим по логу, что ни одно это событие не обрабатывается, значит полученный контент будет выводиться без изменений.

Controller 1 'content' end


Говорит о том, что в этом месте завершилась работа контроллера. Причём уже известно имя контроллера 'content' и оно выводится в лог.

Кстати, логи контроллера и хуков будут полезны разработчикам компонентов. Так как позволяют увидеть, какие именно части компонента вызывают тормоза: основная часть (обработка контроллером контента/данных) или хуки этого контроллера.

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

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

Поскольку я открывал страницу под залогиненным админом, то мы видим события, связанные с сообщениями на сайте, и их обработку:

Event 6 'menu_messages'
Hook 2 'menu_messages ‡messages'
Event 7 'menu_messages'
Hook 3 'menu_messages ‡messages'


Далее обработка модерации:

Event 8 'menu_moderation'
Hook 4 'menu_moderation ‡moderation'


Меню групп, контента и администрирования я уже приводить не буду. Вы можете сами посмотреть их в логе.

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

Rendering 1 'default' start
Rendering 1 'default' end — 3.9 ms


Как мы видим, рендеринг страницы в дефолтном шаблоне происходит очень быстро, всего за 3.9 мс.

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

Event 14 'engine_stop'


Это последнее событие, которым система уведомляет компоненты о завершении своей работы. В демо-версии это событие не обрабатывается ни одним компонентом. Но для ваших целей оно может оказаться полезным.

Честно говоря, после этого события происходит ещё остановка кэша. Но фиксировать это в логах я не считаю нужным. Как и его старт тоже. Достаточно того, что подсчитываются и логируются все операции с кэшем, если он включён.


Итого, мы наглядно увидели схему работы системы:

Запускается файл index.php.
— Загружается и инициализируется шаблон сайта.
— Стартует движок системы.
— Выполняется роутинг;
Контроллер обрабатывает данные необходимым образом;
— Подготавливаются дополнительные блоки страницы: меню, виджеты.
— Из подготовленных html-текстов собирается конечная HTML-страница, то есть выполняется её рендеринг.

Полученная схема как раз укладывается в схему из документации. То есть, мы действительно увидели работу InstantCMS 2 изнутри на примере одной из страниц.
Таким же образом вы можете изучить любую страницу вашего сайта и посмотреть, что именно на ней происходит. И даже более того.

Совет: Над некоторыми значениями и именами курсор мышки меняется на вопросительный знак и появляется всплывающая подсказка. Поводите мышкой над основной таблицей и строчками лога, получите краткое описание этих значений.

Примечание: Все цифры времени и памяти я привёл для своего компьютера и установленных программ. У вас эти значения будут отличаться от моих.

Что ещё будет полезно тем, кто хочет изучить работу InstantCMS 2 и на уровне кода тоже?

Можно включить показ виджетов, как я уже написал выше. Это позволит увидеть, в какие именно моменты выводятся виджеты. Вы заметите, что некоторые события происходят во время вывода виджетов. Убедитесь, что рендеринг страницы происходит действительно после подготовки всех виджетов и меню.

Можно включить галку «Показ данных и результатов хуков». Тогда вы увидите полную информацию о событиях и хуках, включая передаваемые им системой данные и возвращаемые данные (если таковые есть). Такую же галку можно включить и для виджетов.

Трассировка однозначно будет полезна тем, кто хочет понять, как работает система на уровне кода. Она позволяет наглядно увидеть всю цепочку, откуда и кто вызвал любое действие, зафиксированное в логе. Её можно включить в настройках отладки для каждого фиксируемого типа лога отдельно, выбрав желаемую глубину трассировки этого элемента лога от 0 (отключить) до 20 (глубина 20 вызовов, хватит для любых случаев).

Любопытные пользователи могут включить показ SQL-запросов, автозагрузок и инклудов. Так, например, можно легко увидеть, какие запросы выполняются той или иной частью системы. А также получить массу дополнительной информации. Немного про SQL-запросы я писал в предыдущих частях своего блога.

Можете поиграться фильтрами в отладке. С их помощью можно, например, получить логи (или часть логов) только выбранного компонента. А поскольку основная деятельность в системе происходит с помощью компонентов и их контроллеров, хуков, виджетов, то фильтры очень удобны для выборки нужных логов.

А самым продвинутым исследователям и разработчикам рекомендую воспользоваться точками отладки, вставляемыми в любое место кода (смотрите справку по использованию отладки). Получите незабываемые ощущения любую подробную информацию обо всём происходящем в этом месте системы.

Более подробно про возможности «Расширенной отладки» для разработчиков я постараюсь рассказать в следующих постах этого блога. Не переключайте канал! 😊

В этом материале я описал своё понимание работы InstantCMS 2. Если я где-то ошибся или что-то не так сформулировал, просьба к разработчикам поправить меня – я исправлю в тексте.

Спасибо разработчикам за очень удачную реализацию движка!
+1
Alexprofi Alexprofi 8 лет назад #
Пока еще не разобрался (да и не было времени разбираться), но чувствую что разработка очень полезная,
а энтузиазм и упорство с которым автор продвигает свое детище, вызывает огромное восхищение и уважение.
+1
WebMan WebMan 8 лет назад #
Спасибо за добрые слова, Alexprofi!
0
lezginka.ru lezginka.ru 8 лет назад #
+
...необычная разработка...отличное пособие для преподавателей...
Олег Васильевич я Олег Васильевич я 8 лет назад #
Комментарий удален
+1
Loadырь Loadырь 8 лет назад #
Думаю, пора пулреквест на гите писать.

Еще от автора

Хуки-хухуки: Исключаем неактивных пользователей из списков
Как иногда начинают свой монолог неопытные стендаперы: «У всех в жизни было такое …
«Расширенная отладка» для InstantCMS 2.14.1 (v.14.1.2) – большое обновление для разработчиков
Новые возможности и удобства, облегчающие разработчикам отладку компонентов и шаблонов.
Использование расширенной отладки. Часть 11. Анализ ошибок 403/404 и редиректов
Одной из неудобных задач при отладке для меня является поиск причины ошибки 403/404.
Используя этот сайт, вы соглашаетесь с тем, что мы используем файлы cookie.