Рекомендации по профилированию PHP приложений

В этой статье я расскажу, что такое профилирование и покажу на примере конкретных профилировщиков как происходит этот процесс.

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

Для профилирования используют специальный инструмент – профилировщик. Он измеряет показатели работы программы, например использование памяти или процессорного времени.

Показатели, которые измеряются при профилировании:

• Время исполнения программы
• Затраченное процессорное время
• Количество вызовов функций
• Выделенная и используемая память
• Операции ввода-вывода

Выбрать подходящий инструмент

Xdebug — Часть PHP-расширения Xdebug, реализующая профилирование выполнения скриптов на уровне функций. Xdebug работает как расширение для Zend Engine. Он добавляет «хуки» для вызовов функций, конструкторов, деструкторов и методов классов. Это гарантирует высокую точность, но может существенно замедлить выполнение кода (по информации из разных источников исполнение замедляется от 2х и вплоть до нескольких десятков раз), поэтому подходит только для локальной отладки.

XHProf — это легковесный профилировщик, основанный на иерархии и инструментировании. В процессе сбора данных он отслеживает количество вызовов и инклюзивные метрики вызовов программы. Эксклюзивные метрики, такие как затраченное время, время CPU и потребление памяти, рассчитываются в фазе постпроцессинга.

Blackfire — комплексное решение для непрерывного наблюдения, позволяет вам отслеживать поведение ваших приложений в реальном времени. Имеет низкие накладные расходы, так как по умолчанию профили работают на основе синтетических запросов, не создавая накладных расходов. Имеет удобное графическое представление собранных профилей. В отличие от XHProf и Xdebug является платным сервисом.

PHP-SPX — бесплатный open-source проект. Имеет неплохую встроенную визуализацию профилей. Но автор не рекомендует использовать в продакшен-среде, так как это всё ещё экспериментальная версия, и API может изменяться или проект в целом может быть заброшен.

Tideways — коммерческий наследник XHProf с поддержкой современных PHP-версий, удобной визуализацией и интеграцией в CI/CD. Подходит для staging и production.

New Relic — платформа APM для мониторинга PHP-приложений в production. Дает метрики по времени отклика, нагрузке на базу данных и сервер. Сервис является платным, хотя и имеет бесплатную версию с некоторыми ограничениями.

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

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

XHProf — это иерархический профилировщик для PHP. Компонент сбора необработанных данных реализован на языке C в виде расширения PHP Zend под названием xhprof. XHProf позволяет получить следующую информацию:

Какие функции запускались

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

Время выполнения функции

Мы можем собирать 2 параметра времени:

• Время выполнения функции (Wall Time) — включает в себя не только время выполнения кода в PHP, но и время ожидания операций ввода-вывода, работы с сетью, базами данных и других внешних сервисов
• Процессорное время (CPU Time) — время, в течение которого процессор был занят выполнением кода вашего приложения.

Например, для вызова sleep(1)

	Wall Time ~ 1005967  
	CPU Time ~ 205

Важно заметить, что подсчёт CPU Time — довольно затратная операция. Процессорный таймер (getrusage) в Linux имеет высокие накладные расходы. Он также имеет грубую точность (с точностью до миллисекунд, а не до микросекунд), что делает его полезным на уровне функций. Поэтому искажение данных о времени работы функции при использовании режима XHPROF_FLAGS_CPU, как правило, выше.

Для подсчёта времени выполнения профилировщик использует инструкцию RDTSC (счётчик временных меток) для реализации таймера прошедшего времени с минимальными накладными расходами. Поэтому в настоящее время xhprof работает только на архитектуре x86. Кроме того, поскольку значения RDTSC могут быть не синхронизированы между процессорами, xhprof привязывает программу к одному процессору на время профилирования.

Потребление памяти

Учтите, что профилировщиком не отслеживается строго каждая операция выделения/освобождения памяти. Вместо этого отслеживается увеличение/уменьшение объёма памяти, выделенной PHP, между входом и выходом каждой функции. Он также отслеживает увеличение/уменьшение пикового объёма памяти, выделенной PHP для каждой функции. Данная метрика собирается только в режиме XHPROF_FLAGS_MEMORY.

Иерархический профилировщик

Что же скрывается за фразой "иерархический профилировщик"? Когда профилировщик получает информацию о работе программы, он считает, сколько раз функция bar (родитель) вызвала функцию foo (потомок) и сколько ресурсов на это ушло. Это накладывает некоторые ограничения, например: мы не можем отделить стек вызова car()->foo()->bar() от map()->foo()->bar(), всё что мы можем – это знать, что функция foo вызывала функцию bar n-раз и увидеть время и ресурсы, потраченные на выполнение. Поэтому важно помнить, что если у нас время выполнения функции зависит от входных параметров, то может возникнуть ситуация, когда в контексте map()->foo()->bar() функция будет выполняться быстро, а в контексте car()->foo()->bar() — медленно или потреблять большее количество ресурсов. Но профилировщик покажет нам только, что стек foo()->bar() выполнялся долго. Поэтому важно правильно локализовать проблему. Для этого нужно брать во внимание не только сырые данные, но и постпроцессинг, чтоб отделить инклюзивные показатили от екслюзивных.

Подробнее рассмотрим на примере:

function bar(Object $obj) :void{
	  // ... какие-то трудозатратные опреции c $obj. 
}

/** 
 * @param list<list<Object>>
 */
function foo(array $y) :void{

	// ... какая-то обратка $y
	
	$values = [];
	foreach($y as $value){
		array_push($values, ...$value); 
	}

	bar($values)
}

function map() :void{
	foo([ new Object(1) ])
}


function car() :void{
	$values = array_fill(0, 10_000, new Object(2))
	
	foo($values);
}

Результаты:

В стеке cat()->foo() был один вызов и wall time 100 мс.
В стеке map()->foo() был один вызов и wall time 20 мс.
В стеке foo()->bar() было 10К вызовов и wall time 60 мс.

Визуализация профиля и постпроцессинг

Сырые данные XHProf трудно анализировать вручную, а поставляемый с XHProf инструмент для визуализации сильно устарел (там ещё jQuery используется 😁). Для визуализации можно использовать Buggregator — удобный инструмент для сбора и отображения профилей.

Buggregator — это бесплатный серверный инструмент, разработанный для отладки PHP-приложений. Он предлагает 3 варианта визуализации профилей:

• Call Graph — отображает вызовы функций в виде древовидной структуры. Цвет узлов в дереве вызовов варьируется от белого до тёмно-красного.

• FlameGraph — это графическое представление стека вызовов функций и показывает, какие функции вызываются какими другими функциями.

Top 100 Functions — в этой таблице перечислены 100 основных вызовов функций, потребляющих больше всего ресурсов.

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

Этот инструмент также проводит постпроцессинг данных и предоставляет следующую информацию о работе той или иной функции:

• Inclusive Time (или Subtree Time) — включает время, затраченное в самой функции, а также во всех дочерних функциях, которые были вызваны из неё.
• Exclusive Time / Self Time — измеряет время, затраченное только внутри самой функции. Не включает время, потраченное на вызовы дочерних функций.
• Wall Time — общее время выполнения.
• CPU Time — время работы процессора.

Buggregator поставляется как Docker-образ, который предоставляет вам не только визуализацию, но и сохранение профилей. У него есть свой API, а также БД, что позволяет легко настроить автоматическое сохранение профилей. Также не составляет большого труда запустить Buggregator в облаке, чтоб один экземпляр Buggregator-а мог обрабатывать сразу несколько ваших сервисов. Для облегчения поиска профиля есть возможность указать, с какого сервиса/проекта собран данный профиль.

Для лёгкого внедрения в проект и проведения профилирования есть готовые интеграции:

• spiral-packages/profiler — подключается к приложению и автоматически отправляет профили XHProf в Buggregator.
• iluckhack/xhprof-buggregator-bundle — интеграция с Symfony, позволяющая собирать и визуализировать профили без дополнительной ручной настройки.

Запуск профилировщика на разных окружениях

Выборочное профилирование
Запускать профилировщик на 100% трафика не имеет смысла, так как вы просто утонете в огромном количестве информации и рискуете "не увидеть лес из-за деревьев". Достаточно будет собрать профили с небольшого процента трафика — так вы получите всю нужную информацию, и большинство пользователей не заметит, что сервис стал отвечать дольше.

Правильная конфигурация
Как мы говорили выше, XHProf хорошо справляется с тем, чтобы измерять время выполнения, и хуже — с измерением процессорного времени. При планировании оптимизаций подумайте, а нужно ли вам собирать тот или иной профиль нагрузки. Если ваши метрики показывают, что вы не потребляете слишком много процессорного времени и памяти, но при этом у вас повышено время ответа от сервера, возможно, для начала стоит собрать только Wall Time профиль.

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

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

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