Liveprof покажет, когда и почему менялась производительность вашего PHP-приложения

Привет! Меня зовут Тимур Шагиахметов, я PHP-разработчик в Badoo ^[1].

Производительность приложения — один из важнейших критериев качества работы программиста. В вопросах оптимизации PHP-приложений помощником является профайлер.

Недавно мы рассказывали ^[2] о том, какими инструментами пользуемся для профилирования. Напомню: одним из инструментов для анализа производительности, когда непонятно, какие части кода повлияли больше всего на увеличение времени формирования ответа, является XHProf ^[3]. Это расширение для PHP, которое позволяет профилировать код на боевом сервере и впоследствии  улучшать его.

Но хотелось бы ещё иметь историю изменения производительности, чтобы можно было отследить, что и когда повлияло на её ухудшение, не так ли? Для этого около года назад мы разработали Liveprof ^[4] — инструмент для автоматического профилирования всех запросов с интерфейсом для анализа изменения производительности приложения.

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

В этой статье я расскажу о деталях реализации и особенностях использования этого инструмента.

Немного об XHProf

Для начала несколько слов о возможностях самого XHProf. Это профайлер для PHP, написанный на C как расширение. Он был разработан в Facebook и выложен в открытый доступ. Имеет несколько форков (uprofiler ^[5], Tideways ^[6]), полностью совместимых на уровне формата выходных данных.

XHProf расставляет таймеры вокруг всех вызовов функций/методов. Его использование сопряжено с некоторыми накладными расходами. Но они не такие большие и позволяют использовать его в продакшене.

Результатом работы XHProf является массив элементов в следующем формате:

$data = [
   'parentMethodName==>childMethodName' => [
        'ct' => 1
        'wt' => 8
        'cpu' => 11
        'mu' => 528
        'pmu' => 0
    ]
];

, где

parentMethodName и childMethodName — родительский и дочерний методы соответственно;
ct — количество вызовов в контексте запроса;
wt — время выполнения запроса (состоит из времени, затраченного процессором, и времени ожидания ввода/вывода или ответа другого сервиса);
cpu — время, затраченное процессором на обработку запроса;
mu — изменение потребления памяти после вызова метода;
pmu — изменение пикового потребления памяти после вызова метода.

Также возможно наличие некоторых других параметров.

XHProf также содержит инструменты для визуализации полученных таким образом результатов. Для каждой операции профилирования получаем таблицу с набором параметров по каждому методу.

Например,

<?php

class ArrayGenerator
{
    public function getRandomArray(int $count): array
    {
        $array = [];
        for ($i = 0; $i < $count; $i++) {
            $array[] = rand(0, 1000);
        }
        return $array;
    }
}

class BubbleSorter
{
    public function sort(&$array): void
    {
        $len = count($array);
        for ($i = 0; $i < $len ; $i++) {
            for ($j = 0; $j < $len - $i - 1; $j++) {
                if ($array[$j] > $array[$j + 1]) {
                    $this->swap($array[$j], $array[$j + 1]);
                }
            }
        }
    }

    private function swap(&$a, &$b): void
    {
        $tmp = $a;
        $a = $b;
        $b = $tmp;
    }

    public function isSorted(array $array): bool
    {
        $len = count($array);
        for ($i = 0; $i < $len - 1; $i++) {
            if ($array[$i] > $array[$i + 1]) {
                return false;
            }
        }

        return true;
    }
}

class ArrayPrinter
{
    public function print(array $array, string $delimiter = ' '): void
    {
        echo implode($delimiter, $array) . PHP_EOL;
    }
}

xhprof_enable();

$n = 10;
$arrayGenerator = new ArrayGenerator();
$array = $arrayGenerator->getRandomArray($n);

$sorter = new BubbleSorter();
if (!$sorter->isSorted($array)) {
    $sorter->sort($array);
}

$printer = new ArrayPrinter();
$printer->print($array);

$xhprof_data = xhprof_disable();

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

Также можно посмотреть на граф вызовов с подсветкой самых ресурсоёмких методов:

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

Liveprof: агрегируем результаты и храним историю

Как получить историю профилирования?

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

У нашего инструмента есть и преимущества, и некоторые ограничения.

Что умеет агрегатор:

1. Автоматическое профилирование каждого N-го запроса.
2. Ежесуточное агрегирование собранных профилей.
3. Возможность посмотреть графики изменения каждого параметра, измеренного профайлером. Например, wt, cpu,  mu, pmu, описанные выше.
4. Посмотреть изменение производительности любого метода за определенный интервал.
5. Флеймграф ^[7], построенный по последним агрегированным данным.
6. Найти запросы, в которых вызывался определенный метод

Ограничения:

1. Поскольку наш инструмент — агрегирующий, нельзя узнать производительность одного запроса (например, самого медленного) — результаты получаем усреднённые за последние сутки. Но этого достаточно, чтобы оценить общую динамику производительности. Если какой-то запрос просел в скорости выполнения, то изменятся среднее значение, 95-й перцентиль и максимальное время выполнения.
2. Нельзя однозначно восстановить полный стек вызова, так как XHProf возвращает только уникальные пары «родитель — потомок» с суммой значений затраченных ресурсов.
3. Погрешность времени выполнения запросов, связанная с накладными расходами XHProf. Разница не такая и большая, но ее надо учитывать при измерении времени выполнения запроса.

Как использовать профайлер

1. Для начала профайлер нужно подключить к сайту или скрипту. Удобнее всего использовать инструмент для автоматического запуска профайлера ^[8]:

   php composer.phar require badoo/liveprof
   
   # Run a script to configure database
   LIVE_PROFILER_CONNECTION_URL=mysql://db_user:db_password@db_mysql:3306/Profiler?charset=utf8 php vendor/badoo/liveprof/bin/install.php
   

   Он поддерживает версии PHP начиная с 5.4, и его использование сопряжено с минимальными накладными расходами, что позволяет использовать его в боевом окружении. Инструмент  автоматически определяет используемое расширение профайлера: XHProf ^[3], uprofiler ^[5] или Tideways ^[6]. При запуске нужно указать параметры подключения к базе данных и настройки профилирования.

   Пример использования в коде с настройками по умолчанию:

   <?php
   include 'vendor/autoload.php';
   
   BadooLiveProfilerLiveProfiler::getInstance()->start();
   // Code is here

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

   Сейчас доступны следующие:

   • минимум за день;
   • максимум за день;
   • среднее значение за день;
   • 95-й перцентиль за день.

2. Для настройки агрегации и просмотра результатов используется веб-клиент агрегатора ^[4]. Проще всего его установить в докер-контейнере:

   git clone https://github.com/badoo/liveprof-ui.git
   cd liveprof-ui
   docker-compose up web

3. Перед первым запуском нужно настроить параметры подключения к базе данных, список полей и используемых агрегированных функций в файле конфигурации src/config/services.yaml. Затем выполнить скрипт установки:

   docker-compose exec web bash install.sh

4. Надо прописать в крон автоматически запускаемые скрипты агрегации и очистки старых данных:

   # script aggregates all profiles for previous day, add it if you don't use a queue for aggregation jobs (parameter aggregator.use_jobs_in_aggregation=false)
   0 2 * * * docker-compose -f %PATH_TO_PROJECT%/docker-compose.yml run --rm  --entrypoint '/usr/local/bin/php /app/bin/cli.php cron:aggregate-all-profiles' web
   # script removes old aggregated data, by default > 200 days
   0 1 * * * docker-compose -f %PATH_TO_PROJECT%/docker-compose.yml run --rm  --entrypoint '/usr/local/bin/php /app/bin/cli.php cron:remove-old-profiles' web 200

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

   docker-compose exec web php /app/bin/cli.php example:a-week-degradation

Описание интерфейса

Веб-интерфейс доступен по адресу: 127.0.0.1:8000.

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

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

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

Страница с флеймграфом ^[7] последнего агрегированного запроса позволяет визуально определить самые тяжелые части.

Использование XHProf накладывает некоторые ограничения по точности результата. Это связано с тем, что профайлер не возвращает полное дерево вызовов, а только пары «родитель — потомок». При этом если какая-то пара методов вызывалась из разных мест приложения, то в результате получим сумму затраченного времени. Для флеймграфа нужно  иметь полное дерево вызовов.  При восстановлении такого дерева значения параметров нормализуется с учетом времени, затраченного родителями.

Страница со списком методов, которые стали работать медленнее в течение выбранного интервала.

Также по каждому методу можно посмотреть, какой из дочерних вызовов повлиял больше всего на производительность. Например, на скриншоте ниже можно увидеть, что метод ServiceApi::getAvailableServices() стал выполняться на 116 мс медленнее. Причиной тому стало добавление вызова ServiceApi::getGifts() (изменение на 56 мс) и увеличение числа вызовов метода ServiceApi::getConfigForList() с 1 до 5 (еще 50 мс):

^[9]

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

Страница с поиском запросов, в которых вызывался конкретный метод.

Она позволяет сравнить время исполнения в разных запросах. Полезна также в поиске неиспользуемого кода:

Возможности кастомизации

Инструмент имеет широкие возможности для кастомизации:

• можно добавить собственные агрегирующие функции, которые вычисляют некое значение на основе переданного массива значений параметра;
• можно изменить базу данных для хранения профилей и агрегированных результатов (сейчас поддерживаются SQLite, MySQL и PostgreSQL, но можно использовать и другие из списка доступных для Doctrine DBAL ^[10]);
• можно переопределить как менеджер подключения к базе данных, так и реализовать свои методы получения данных;
• можно использовать веб-интерфейс как в качестве самостоятельного проекта, так и внутри любого фреймворка (например, панели управления сайтом). Пример:

  public function profileListAction()
  {    
      <i>//Some custom logic before</i>
      $this->checkPermissions();
  
      $App = new BadooLiveProfilerUILiveProfilerUI();
      $Page = $App->getPage('profile_method_list_page');
      return $Page->setData($data)->render();
  }

Заключение

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

Он доступен на GitHub: github.com/badoo/liveprof ^[11], веб-интерфейс — github.com/badoo/liveprof-ui ^[12].

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

Отзывы и вопросы по использованию присылайте нам в Telegram ^[13], баги и пулл реквесты — прямиком в GitHub ^[14]. Будем рады комментариям и предложениям!

Отдельная благодарность Григорию ^[15] за идею и первую реализацию.

Автор: Timur Shagiakhmetov

Источник ^[16]