Профилирование php-кода

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

Недавно я столкнулся с проблемой в Albireo CMS, которую долго не мог выявить. И когда уже перепробовал все варианты, понял, что нужно заниматься профилированием. Только так получается выявить проблемные места в коде.

Суть проблемы в том, что система стала медленно работать, относительно предыдущих версий. Например раньше система генерировала страницу за 0,1-0,2 секунды, но вдруг стала работать за 0,5-0,9 секунд.

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

Тестирую я систему на нескольких сайтах — у них общее ядро, только разные настройки и количество страниц.

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

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

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

В какой-то момент до меня всё-таки дошло, что это бессмысленно, потому что у меня элементарно нет статистики выполнения по времени тестируемых функций и участков кода.

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

/**
 * Отладка по времени
 * Функция вначале собирает данные в общий массив, а потом выводит его через pr()
 * Работает только если в стоит define('DEBUG_BENCHMARK', '');
 *
 * define('DEBUG_BENCHMARK', ''); // где-то в loader.php
 *
 * debugBenchmarkStart('метка');
 *    любой код
 * debugBenchmarkEnd('метка');
 *
 * debugBenchmarkOut(); // вывод где-то в самом конце кода
 **/

function debugBenchmarkStart($mark)
{
    if (!defined('DEBUG_BENCHMARK')) return;

    // объявляем пременную глобальной, чтобы к ней был доступ у других функций
    // а также потому, что это не требует других зависимостей
    global $debugBenchmark;

    $debugBenchmark[$mark] = hrtime(true);
}

function debugBenchmarkEnd($mark, string $after = '')
{
    if (!defined('DEBUG_BENCHMARK')) return;

    global $debugBenchmark;

    $end = hrtime(true);
    $start = $debugBenchmark[$mark] ?? false;

    if ($start !== false) {
        // наносекунды в миллисекунды
        $time = ($end - $start) / 1e+6;

        if ($after) 
            $debugBenchmark[$mark] = $time . ' # ' . $after;
        else 
            $debugBenchmark[$mark] = $time;
    }
}

function debugBenchmarkOut()
{
    if (!defined('DEBUG_BENCHMARK')) return;

    global $debugBenchmark;

    if ($debugBenchmark) 
        pr($debugBenchmark); // print_r()
}

Функция pr() — это обёртка над print_r(), можно использовать её.

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

Для тестирования функций можно использовать так:

debugBenchmarkStart(__FUNCTION__);

тут тестируемый код

debugBenchmarkEnd(__FUNCTION__);

Если в функции несколько тестируемых участков, то можно делать так:

debugBenchmarkStart(__FUNCTION__);

if (какое-то условие) {
    debugBenchmarkEnd(__FUNCTION__, 'сработало условие');
    return ...
}

debugBenchmarkEnd(__FUNCTION__, 'полная отработка');

Можно спокойно «вкладывать» метки друг в друга:

debugBenchmarkStart(__FUNCTION__);
    
debugBenchmarkStart(__FUNCTION__ . ' 1');
какой-то участок кода
debugBenchmarkEnd(__FUNCTION__ . ' 1');

debugBenchmarkStart(__FUNCTION__ . ' 2');
ещё что-то
debugBenchmarkEnd(__FUNCTION__ . ' 2');

debugBenchmarkStart(__FUNCTION__); // конец функции

Константа DEBUG_BENCHMARK нужна для того, чтобы отключить отладку на рабочем сайте, не удаляя отладочные функции.

На выходе будет что-то вроде такого (время в миллисекундах):

Array
(
   [readPages] => 143.4519 # not cache
   [pageOut] => 149.4376
   [pageOut 1] => 0.163
   [events\stat save] => 110.188
   [pageOut 2] => 0.0123
   [pageOut getContentFile] => 30.4609
   [requireSafe - alpine.php] => 0.2404
   [requireSafe - counter.php] => 0.4861
   [requireSafe - css.php] => 0.6836
   [requireSafe - favicon.php] => 0.3376
   [requireSafe - imfont.php] => 0.1729
   [requireSafe - js.php] => 0.1757
   [requireSafe - splitjs.php] => 0.186
   [requireSafe - tiny-slider.php] => 0.1814
   [requireSafe - wow.php] => 0.1579
   [templateModules - headers] => 0.9585
   [35-nav 1] => 0.4796
   [requireSafe - 40-other-pages.php] => 0.3458
   [requireSafe - 50-comments.php] => 2.9518
   [implodeWrap] => 0.0121
   [templateModules - footers] => 1.4396
   [pageOut processingContent] => 2.3328
   [pageOut compressHtml] => 0.7257
   [pageOut events pageOut-end] => 0.0089
)

Я начал профилирование с блока проверки лицензии и выяснил, что это всего несколько миллисекунд. То есть мои предположения, что этот код может тормозить, оказались ошибочными. Чтобы понять в чём проблема, я начал с проверки основных функций ядра системы. Выяснилось, что основное время это readPages() и pageOut().

Первая функция считывает все файлы в указанном каталоге, включая подкаталоги. У меня есть несколько версий этой функции, крайний вариант работал на glob(), но я решил проверить работу и на RecursiveDirectoryIterator. Оказалось, что они примерно равны, но если запустить их много раз, то glob() показывает примерно стабильные результаты, а RecursiveDirectoryIterator при повторах работает раз в 10 быстрей. Предполагаю, что там используется какой-то вариант кэша из файловой системы ОС. В PHP такое кэширование используется в разных функциях, вроде filemtime(). Таким образом я смог понять где функция тратит своё основное время.

Попутно я выяснил, что можно ускорить INSERT-запросы Sqlite примерно в два раза. При включенной статистике, каждая страница сохраняется в базе, а это INSERT. Зарывшись в доки я поэкспериментировал и выяснил, что если Sqlite указать журналирование в памяти, то это сильно ускоряет транзакцию. Делается это элементарным sql-запросом:

PRAGMA journal_mode=MEMORY;

В итоге это снизило запись в базу примерно до 100 мс. Меньшее значение можно получить только вовсе отключив журнал (OFF), поэтому я не рискнул.

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

Таким образом я подобрался к коду, который получает записи для вывода. Это базовые функции работы с массивом, которые я считал уже отлаженными и быстрыми.

Тестируя на разных сайтах я заметил, что тормозят только те, где много записей — более 100-200 и т.д. С помощью профилирования удалось наконец-то локализовать проблему — это функция сортировки массивов по дате.

Здесь нужно объяснение. В Albireo CMS поле date используется как дата записи, но формат даты может быть произвольным, главное, чтобы его понимала функция strtotime(). Можно было бы конечно зафиксировать какой-то строгий формат даты и времени, но мне хочется больше вольностей для пользователей. Поэтому я и использую эту функцию.

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

Отказываться от strtotime() я не хотел, поэтому сделал немного другой алгоритм. При получении записей все поля дат прогоняются через strtotime() и получается метка времени Unix в дополнительных (скрытых) полях. После этого страница попадает в кэш. Функция сортировки массива сама проверяет поле — и если это дата, то использует уже другое поле метки Unix. Таким образом сортировка работает уже по числовым полям, а это очень быстрая операция. В цифрах — это ускорение примерно в 100 раз.

Такая оптимизация привела к увеличению скорости Albireo CMS. Если бы не профилирование кода, то можно было бы гадать до сих пор где проблема.

Слава Украине! Смерть рашистам!