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

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

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

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

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

Сбор данных

$timer = pinba_timer_start(array('tag' => 'some_logic'));
....
pinba_timer_stop($timer);

$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);

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

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;

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;

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

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

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

Итого

• Мы разместили 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 секунд

• Купить программу Microsoft: Visual Studio 2010
• Задать вопрос ONLine по покупке программ в интернет магазине ITShop