Профилирование PHP скриптов на живом сервере

    Добрый день, сообщество!

    Наверняка кто-то из вас сталкивался с такой проблемой: медленно работает сайт на реальном сервере.
    Важно оперативно выяснить в каких местах возникли сложности. Использовать для этого xdebug нельзя, так как он создает большую нагрузку на сервер и сам вносит погрешность в измерения. Для решения этой задачи мы выбрали систему, которая позволяет очень быстро собирать древовидную статистику по работе сайта — pinba.

    На хабре уже рассказывали о специфике работы с pinba. Если вы не читали, можете ознакомиться по ссылке.

    Для нетерпеливых сразу дам ссылку на результат.
    Plus1 WapStart работает в штатном режиме при нагрузке более 1000 запросов в секунду на один инстанс.

    Как это все работает?


    Сбор данных

    Pinba отправляет на свой сервер (по UDP, очень быстро) метки начала и конца отрезка времени (далее — таймеры) и складывает данные в MySQL таблицы (легко прочитать). Например
    $timer = pinba_timer_start(array('tag' => 'some_logic'));
    ....
    pinba_timer_stop($timer);
    

    Для построения древовидной структуры мы добавляем 2 дополнительных тега — tree_id (каждый раз уникальный id) и tree_parent_id — это tree_id от того таймера, в который вложен текущий. Например

    $parent_timer = pinba_timer_start(array('tag' =>'some_logic', 'tree_id' => 1, 'tree_parent_id' => 'root'));
    
       $child_timer = pinba_timer_start(array('tag' =>'child_logic', 'tree_id' => 2, 'tree_parent_id' => 1));
       pinba_timer_stop($child_timer);
    
    pinba_timer_stop($parent_timer);
    

    Таким образом, на сервере можно воспроизвести вложенность таймеров и построить удобочитаемое дерево.
    Мы разместили во всех интересных местах проекта таймеры, чтобы засекать время (например, при sql запросах, при записи в файлы и т.д.).

    Подготовка данных

    К сожалению, pinba не использует индексы для запросов (кроме PRIMARY), так как используется свой pinba ENGINE (таблицы фактически хранятся в memory, и данные старше N минут удаляются, в нашем случае — 5 минут). Но нельзя сетовать на pinba, так как она предназначена не для запросов по индексам.
    Для нас индексы важны, потому мы копируем все данные из таблиц pinba в обычные MyISAM таблицы.

    truncate table pinba_cache.request;
    truncate table pinba_cache.tag;
    truncate table pinba_cache.timer;
    truncate table pinba_cache.timertag;
    
    insert ignore into pinba_cache.request select * from pinba.request;
    insert ignore into pinba_cache.tag select * from pinba.tag;
    insert ignore into pinba_cache.timer select * from pinba.timer;
    insert ignore into pinba_cache.timertag select * from pinba.timertag;
    

    Как видно из запросов, у нас система работает в базе pinba, а копия — в базе pinba_cache.

    Так же для работы нам понадобится ещё одна таблица, в которой будут поля tree_id и tree_parent_id.

    truncate table pinba_cache.timer_tag_tree;
    insert ignore into pinba_cache.timer_tag_tree
    SELECT * FROM (
    	SELECT null, timer_id, request_id, hit_count, timer.value, GROUP_CONCAT(timertag.value) as tags
    	, (select timertag.value from pinba_cache.timertag where timertag.timer_id=timer.id and tag_id = (select id from pinba_cache.tag where name='treeId')) as tree_id
    	, (select timertag.value from pinba_cache.timertag where timertag.timer_id=timer.id and tag_id = (select id from pinba_cache.tag where name='treeParentId')) as tree_parent_id
    	FROM pinba_cache.timertag force index (timer_id)
    	LEFT JOIN pinba_cache.timer ON timertag.timer_id=timer.id
    	where not tag_id in ((select id from pinba_cache.tag where name='treeId'), (select id from pinba_cache.tag where name='treeParentId'))
    	group by timertag.timer_id
    	order by timer_id
    ) as tmp
    GROUP BY tree_id;
    

    Структура таблицы timer_tag_tree приведена ниже. Структура остальных таблиц такая же как в pinba.

    CREATE TABLE `timer_tag_tree` (
    	`id` INT(10) UNSIGNED NOT NULL AUTO_INCREMENT,
    	`timer_id` INT(10) NOT NULL DEFAULT '0',
    	`request_id` INT(10) NULL DEFAULT NULL,
    	`hit_count` INT(10) NULL DEFAULT NULL,
    	`value` FLOAT NULL DEFAULT NULL,
    	`tags` VARCHAR(128) NULL DEFAULT NULL,
    	`tree_id` VARCHAR(35) NOT NULL DEFAULT '',
    	`tree_parent_id` VARCHAR(35) NOT NULL DEFAULT '',
    	PRIMARY KEY (`id`),
    	INDEX `timer_id` (`timer_id`),
    	INDEX `tree_id_tree_parent_id` (`tree_id`, `tree_parent_id`),
    	INDEX `tree_parent_id_tree_id` (`tree_parent_id`, `tree_id`)
    )
    COLLATE='utf8_general_ci'
    ENGINE=MyISAM
    

    Анализ данных

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

    Алгоритм объединения следующий:

    Для каждого узла считаем сумму времен выполнения этого узла по всем деревьям.
    Написав функцию для объединения двух деревьев, можно пройтись циклом по всем и получить сумму.
    Но тут нас ждет неприятный сюрприз — медленное время работы.
    Как видим из картинки, сложность объединения 2 деревьев — O(N*N) (внимательные мне подскажут, что можно сделать это за N*log(N), но далее будет более простой метод оптимизации, в 3 строчки), где N — к-во узлов в дереве. Соответственно выгодно объединять маленькие деревья, и очень невыгодно большие.
    Постараемся эту особенность использовать. Давайте определим дерево выполнения одного скрипта как дерево 1 уровня, сумма двух деревьев первого уровня — дерево второго уровня и т.д. В таких терминах нам нужно объединять побольше деревьев первого уровня, и минимум большого уровня. Делать это будем так:

    как видим, суммарное к-во объединений было N-1, из которых N/2 — первого уровня, N/4 — второго уровня, N/8 — третьего и т.д.
    Реализуется эта хитрость крайне просто с помощью рекурсии (при желании её можно разложить в цикл, но для большей понятности я этого делать не буду).

    //принимает на вход массив деревьев, на выход - объединенное дерево
    function mergeTreeList(array $treeList) {
        if (count($treeList) > 2) {
            return mergeTreeList( половина($treeList), вторая_половина($treeList));
        }
        //...
        //тут идет код объединения
    }
    

    Таким образом, мы сначала объединим изначальные деревья в 2х, а потом уже их будет объединять в деревья побольше. Выигрыш по времени у нас составил в ~10 раз (1000 деревьев).

    Итого


    • Мы разместили pinba-таймеры в нашем приложении, где посчитали нужным
    • Мы сформировали агрегированное дерево выполнения на основании многих запросов к скриптам
    • По построенному дереву можно анализировать узкие места проекта, можно строить графики скорости выполнения отдельных кусков проекта
    • Все это происходит прямо на живом сервере с большой нагрузкой


    Подводные камни и минусы


    • На нашем проекте пинба так быстро пишет (и удаляет старое), что запрос insert into table_copy select * from table копирует в 2-3 раза больше данных, чем изначально было в таблице. Потому на время копирования таблиц нужно останавливать запись в pinba (я останавливал сеть на сервере фаерволом)
    • Pinba потребляет много памяти (у нас — 2 Gb чтобы хранить данные за 5 минут), так как мы вместо одного тега пишем 3 (+tree_id, +tree_parent_id)
    • При копировании приходится отключать сеть, чтобы остановить запись в таблицы (на 5-10 секунд), из-за чего теряются данные за эти 5-10 секунд


    Полезные файлы:
    Скрипт для отображения дерева: index.php
    MySQL скрипт для преобразования данных cron.sql
    PinbaClient.class.php — обертка над pinba для более удобного использования с автоматическим добавлением tree_id, tree_parent_id
    Так же хочется упомянуть фреймворк onphp, в котором есть нативная поддержка pinba
    https://github.com/ents/pinba-php-profiler/ — исходные файлы, чтобы поднять все у себя
    http://pinba.org/ — тут можно скачать pinba


    Дисклаймер: Данная статья носит популярный характер и не может рассматриваться как руководство к действию. Все действия, описанные ниже не есть истина в последней инстанции, а скорее один из немногих способов сделать визуализацию информации из pinba
    WapStart
    27,00
    Компания
    Поделиться публикацией

    Комментарии 59

      +3
      Дополню тему: Профилирование php-кода — моя входная статья на хабр была почти о том же, только с применением XHProf. Я так же профилировал на боевом.
        0
        Поддерживаю, xhprof справляется на ура, почти не тормозит, а по файлам данных можно строить весьма удобные dot-графы и быстро найти ошибку.
          +1
          Всё-таки, Pinba и XHProf решают немного разные задачи.
          Пинба изначально расчитана на много серверов, которые требуют постоянного мониторинга, а не профайлинга по клику разработчика.
            0
            С этой стороны — да, я имел в виду непосредственно поиск тормозящего места.
              0
              >непосредственно поиск тормозящего места.
              в realtime, 24/7 — это та задача, которую решают пинба + графики, да.
                0
                Тут ещё анализируется не один скрипт, а объединенные план выполнения многих запросов к серверу
                Ведь тормозное место может прятаться за логикой и не всегда проявляться
                  +1
                  У нас это выглядит как не очень сложный скрипт, который выводит все скрипты из report_by_script_name, отсортированные по суммарному времени исполнения; имя каждого скрипта — ссылка на разбивку самого скрипта по тагам из отчета по тагу «операция»; в ней каждый таг — ссылка на разбивку по серверам из отчета по тагам «операция»+«сервер».
                  Таким образом, с каждым кликом попадаешь на следующий уровень детализации.
                  Чувствую, надо его включить с дистриб пинбы. Поговорю с народом про это…
                    0
                    Это было бы очень полезно.
          0
          я останавливал сеть на сервере фаерволом

          Да уж.

          А чем банальное решение «в лоб» вроде
          define('PINBA', true);
          if(PINBA) {
            $timer = pinba_timer_start(array('tag' => 'some_logic'));
          }
          ....
          if(PINBA) {
            pinba_timer_stop($timer);
          }
          

          Не устраивало?

          Поменять одну константу на время перезаписи таблиц гораздо лучше, на мой взгляд, чем отрубать сеть и лишать всех посетителей доступа к сайту
            +1
            Константу хорошо менять, если у вас один сервер с приложением :) А если их 10-20?
              +1
              например, сохранить эту константу в базе данных пинбы и сделать чтобы пинба складывала данные только если она тру
                0
                для этого нужно переписывать исходники пинбы. А с фаерволом — это одна команда.
                Заблокировали порт, разблокировали порт
                  +2
                  Достаточно ini_set(«pinba.enabled», false);
                  Данные будут собираться, но отсылаться на сервер не будут.
                    0
                    верно, и хорошо работает в случае одного сервера
                    Если же серверов несколько — это становится проблематично
                      0
                      Ну, раскладка бинарников и конфигурации на много серверов — это отдельная задача, каждый её решает по-своему.
            –1
            «Я почти никогда не пользуюсь отладчиком. Я пишу свои программы так, чтобы они выводили в лог всю необходимую информацию, по которой можно понять что происходит. В большинстве случаев я могу понять что не так с кодом по лог файлу без всякой помощи отладчика.» (с)

            Все это к тому, что лучше все же искать проблему по логам как мне кажется, хотя и сам знаю, что не всегда это получается
              +2
              По сути мы и сделали логирование, только в более удобном виде (мы из логов собираем дерево и храним логи только за последние 5 минут)

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

                  Лично мне бы хотелось что бы у таймеров была вложеность на уровне самой пинбы (поле parent_id в таблице timertag вполне подойдет). Тогда бы не пришлось делать work-around для этого. И можно было бы строить дерево выполнения более быстро и красиво
                    0
                    Какая-то у вас очень странная структура с деревьями…
                    Есть внешние сервисы — базы, менеджеры очередей, кэши и т.п.
                    Не знаю где тут дерево можно применить, по-моему всё довольно плоско и просто.
                    'service'=>'db', 'op'=>'insert'
                    'service'=>'cache', 'op'=>'get'
                    Далее отчет по тагам сразу отвечает на вопрос сколько времени, в каком скрипте и сколько раз выполняются инсерты в базу или геты из кэша. Ничего даже делать не надо.
                      0
                      В случае внешних сервисов — да
                      Но в случае покрытия тегами нашей бизнес-логики хочется дерево
                      Например
                      <запросили баннер>
                      <обращение в бд>
                      <обращение в кеш запросов к БД>
                      <получение данных из кеша />
                      </обращение в кеш запросов к БД>
                      </обращение в бд>
                      <возврат результатов />
                      </запросили баннер>
                        0
                        «запросили баннер» — это же сам скрипт, нет?
                        «обращение в БД» и «получение данных из кэша» есть две разные операции, почему одна содержит другую?
                          0
                          ответил в привате. Как дойдем до понимания — отпишусь тут к чему пришли
                            +1
                            Возможно даже отдельной заметкой? Вдруг в процессе обсуждения будет применена текущая схема или что-то новое добавят в pinba.
                        0
                        Дерево позволяет рассчитать сколько кода ещё не покрыто таймерами, на любом уровне вложенности таймеров. А ставить таймеры не только на отдельные запросы вовне, но и на целые функциональные блоки полезно, чтобы отловить нерадивого программиста, написавшего вдруг тормозной цикл.
                    0
                    >штатном режиме при нагрузке около 1000 запросов в секунду на один инстанс
                    Что в данном случаем понимается под инстансом в контексте запущенных процессов? Т.е. этот инстанс это один мастер php процесс и куча рабочих (кстати, сколько?), или это nginx + бэкэндом несколько php мастер процессов?

                    Просто столкнулся с тем, что приложение запущенное на одном мастер процессе и 13 рабочих (3 прозапас) не вытягивало 1000 запросов, хотя по идее должно было (скрипт отрабатываем менее чем за 10 мс, т.е. 1 рабочий процесс может обработать ~100 запросов/сек, а 10 должны 1000). При увеличении потока запросов (что-то около 600 в секунду) наступал момент когда время генерации подскакивало в несколько раз (хотя работа шла с redis-ом по unix socket) и начинали валиться 50х ошибки.

                    Поэтому если возможно, то хотелось бы услышать про архитектуру такого инстанса (один или несколько мастер процессов, сколько воркеров, связь по TCP или по unix socket?) и не пришлось ли тюнить ОС.
                      0
                      Про архитектуру нашего инстанса недавно писал мой коллега — habrahabr.ru/company/wapstart/blog/146520/.
                      Связь непосредственно с pinba происходит по UDP, между nginx frontend и php-backend — по TCP
                      Если статья по ссылке не ответила на ваш вопрос — отпишитесь, я или мой коллега с удовольствием ответим

                      Под 1000 запросов подразумевается 1000 http запросов (это около 50 000 таймеров в секунду для пинбы)
                        0
                        Да, приходилось читать. Но там больше написано про архитектуру приложения в контексте разделения по железу. У меня же больше вопрос о том, 1000 запросов/сек держит связка nginx+php-fpm с одним мастер процессом или же это держит пару (три? больше?) физических серверов? И что понимается под термином «инстанс».

                        Просто из описания той статья складывается впечатление что 1000 запросов держит вся ферма, а не конкретный сервер.
                        0
                        В лимиты (ulimit) не уперлись?
                          0
                          Ну вот я даже приблизительно не могу представить, в какой из них можно было упереться. Связка-то простая: nginx, один unix socket, по нему связь с php-fpm бэкэндом которым по другому unix socket ходит на redis (схема работы «ленивая» поэтому при попадании в кэш не происходит даже коннекта с СУБД). Конечно я в первую очередь подумал про limit, но не могу представить, какой лимит мог сработать. Вторую возможную причину усматриваю в eAccelerator, но он в логах ни на что не ругается.

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

                            Also у php-fpm есть замечательный slow_log. По нему очень легко отслеживать тормоза подсистем.
                              0
                              Нет. Не лимит на файлы точно. Между php-fpm и redis у нас один открытый файл — файл unix socket-а. Возможно я и ошибаюсь, но коннеты от веркеров проходящие по такому сокету не приводят к увеличение счетчика лимитов. Но даже если бы это было так, то воркеров-то только 13 штук, явно сильно меньше даже дефолтного лимита.

                              slow_log лишь скажем нам «о, чувак, у тебя проблемы», но это я знаю и без него ).
                                0
                                Он начнет собирать трейс в момент возникновения проблем. С большой долей вероятности это и будет тормозящий код (ну или код сразу после тормозов).
                                  0
                                  slow_log собирает трейс?! Оо Хм… кажется я отстал от жизни. Пойду погляжу доки.
                                    0
                                    Ни чего нового, я просто уже успел забыть, что он скидывает трейс. Ибо не использую его, т.к. request_slowlog_timeout, подобно MySQL, минимум может быть секунду, а меня в случае тормозов самый долгий скрипт не работает больше 400 мс. Поэтому лог пустой.
                                      0
                                      pinba ставили?
                                      io, la, cpu load какой под нагрузкой?

                                      Надо просто взять и посмотреть. )
                                        0
                                        Свои таймеры юзал. LA и прочее не смотрел, точнее сейчас не помню. Наверное ни чего там криминального не было, если уже подзабыл. Да и какая нагрузка на дедик в 8 ядер и 8Гб который практически ни чего не делает. Хотя да, нужно будет в итоге хорошенько все помониторить.
                          0
                          да, так и есть. 1000 запросов держит вся ферма, но они все обращаются к одной pinba. И существенного увеличения скорости работы скриптов от включения/выключения пинбы не замечалось
                            0
                            Спасибо, понял. Значит с вопросом почему может не тянуть столько запросов один сервер и что бы в ядре потюнить сталкиваться не приходилось.
                              0
                              1000rps на одной машине — это как-бы немного проблематично.
                              Особенно, если скрипты что-то действительно делают, а не просто echo «hello world»;.
                                0
                                Ну я подозреваю, что это проблематично в рамках системы в целом. Просто в топике упомянули 1000rps и один инстанс и мне подумалось, что "о, может народ что-то натюнил в ОС и может рассказать об этом". Но оказалось, что тут про речь о ферме в целом. Но на ферме в целом я думаю и у меня бы проблем не возникло.

                                P.S. Скрипты активно ходят в redis ибо перед началом теста кэш был прогрет и СУБД уже не требуется.
                            –2
                            Не сочтите за рекламу, я никакого отношения к этой компании не имею, но если неохота возиться с pinba или если время разработчика стоит дорого, то стоит посмотреть в сторону NewRelic. 200$/месяц/сервер. Для предприятия — деньги небольшие.
                              +1
                              Деньги, сопоставимые с арендой сервера :)
                                0
                                $200 баксов — много, если серверов больше одного. и closed-source решение — это потеря контроля. вы не сможете ничего поменять, если это вдруг потребуется, или не сможете не менять, когда new relic решит что-то поменять.
                                  0
                                  Кроме футболки у них ничего полезного нет. Подробность статистики там никакущая.
                                  –1
                                  Чем лучше newrelic.com?
                                    0
                                    Ценником, я так думаю. newrelic конечно обещают оптовые скидки на 5+ серверов, но деталей не разглашают.
                                      0
                                      Ценник тоже важно, но newrelic держит довольно таки не плохой зоопарк языков, а как показывает практика не все можно решить на одном языке да и не стоит оно того
                                    0
                                    Использовать для этого xdebug нельзя, так как он создает большую нагрузку на сервер

                                    Справедливости ради стоит отметить, что в xdebug есть возможность делать опциональное профилирование в зависимости от наличия GET-параметра. Так что, в принципе, можно действовать довольно избирательно, например, включать профилирование только для разработчиков или для каждого 1000го запроса. Мне как-то доводилось этим пользоваться. После нахождения тормозов, мы выключали xdebug.
                                      0
                                      xdebug сам вносит погрешности измерения. Сравните, например, доступ к геттеру объекта vs публичного свойства с xdebug и без него.
                                        0
                                        Я об этом прекрасно знаю. Тем не менее, это искажает статистику не настолько, чтобы нельзя было искать узкие места в проекте.
                                        0
                                        xdebug профилирует один запрос к серверу. А предложенная система — показывает агрегированную статистику по многим запросам
                                          0
                                          Это тоже не неразрешимая проблема — агрегировать несколько xdebug-профилей. Но я согласен с вами, что для «многих запросов» и для постоянного мониторинга pinba лучше.
                                          0
                                          для такого профилирования лучше подходит xhprof. у него значительно меньше overhead.
                                          +3
                                          пользуясь случаем, хотел бы прорекламировать: btp-daemon и его веб-интерфейс. который проще в установке и настройке, чем пинба, и сам рисует графики.

                                          но вот такой финт ушами с деревьями сделать, к сожалению, не даст.
                                            0
                                            А кроме pinba-php-profiler нет никаких визуализаторов? Графики построить и т.п…
                                              0
                                              rrdtool?
                                              0
                                              я таких не знаю, но их легко сделать
                                              pinba работает внутри mysql (к ней можно обращаться обычными mysql запросами)
                                              а сервисы вроде zabbix или munin умееют строить графики

                                              То есть схема такая:
                                              1) делаем пхп скрипт, который дергает mysql и получает нужную вам цифру и выводит в stdout
                                              2) Прикручиваем скрипт к заббиксу или мунину для постройки графика по этому скрипту

                                              Если интересно — могу подготовить отдельный обзор как вывести в заббикс (мунин) результаты работы pinba

                                              Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

                                              Самое читаемое