Давайте представим себе типичный, набирающий популярность стартап, использующий, например, PHP или Python. Сначала все находится на одном сервере — PHP (или Python), Apache, MySQL. Затем вы выносите MySQL на отдельный сервер, устанавливаете nginx для раздачи контента, возможно, добавляете memcached для кеширования и еще несколько серверов приложений…
Со временем число серверов будет расти, и рано или поздно вы зададитесь вопросами
«А что сейчас вообще происходит с системой? Как часто выполняется тот или иной скрипт и как долго? Какие операции занимают большую часть времени?» Системы мониторинга типа Zabbix дают лишь общую, поверхностную картину состояния приложения.
Чтобы получить ответы на эти вопросы, в Badoo был разработан сервиc мониторинга и статистики в реальном времени — Pinba. В данной статье мы расскажем о нашем опыте использования его для мониторинга и профайлинга нашей системы.
Чтобы оценить уровень сложности задачи, опишем в нескольких словах, что представляет из себя Badoo. На сегодняшний день у нас функционируют 2 дата-центра, один — в Америке, второй — в Европе. В дата-центрах установлены сотни PHP-серверов, MySQL-серверов, десятки memcached и «самописных» сервисов, написанных на C/C++. Внутри Badoo существуют свои подпроекты (например, веб-сайт, приложения для мобильных устройств и рабочих столов), реализация и характер нагрузок на которые сильно различаются. В одном PHP-запросе могут происходить взаимодействия с десятками различных источников данных (база, кеш, сервис). Это плохо для производительности, но необходимо для решения поставленных бизнес-задач. И вдобавок к этому мы выкладываем новый код от 2 до 5 раз в неделю. Мониторинг производительности такой системы — непростая задача. Pinba помогла решить большой пласт проблем, связанных с мониторингом производительности PHP-скриптов. Данный сервис собирает информацию обо всех обработанных PHP-запросах и формирует подробные отчёты по этим данным.
На Хабрахабре уже была статья о том, как начать работать с Pinba: «Pinba — мониторим php в реальном времени». В ней автор описал, как установить и настроить Pinba, поэтому сейчас мы сконцентрируемся на более интересных вещах: как это всё работает и какую информацию можно получить.
Общая схема работы с Pinba отображена на диаграмме:
Pinba состоит из PHP-модуля (англ. PHP extension) и сервера. Модуль Pinba автоматически шлёт данные обо всех обработанных запросах на сервер. Pinba-сервер — это сервис, написанный на С, который:
Чтобы узнать, что происходит с системой в данный момент, достаточно соединиться с сервером любым MySQL-клиентом и сделать несколько запросов из таблиц-отчётов. Например, можно посмотреть статистику по запросам на каждый из PHP-скриптов (один из наиболее используемых отчётов в Pinba):
Ниже мы подробнее опишем, как работать с отчётами в Pinba.
Еще на этапе планирования первой версии сервиса Pinba сразу же возникла идея организации сбора общей статистики без внесения изменений в PHP-код. Люди, имеющие опыт написания PHP-модулей, знают, что последние имеют возможность выполнять некоторые действия перед каждым запросом (фаза PHP_RINIT) и после его обработки (фаза PHP_RSHUTDOWN). Например, в фазе PHP_RINIT модуль может инициализировать свои внутренние ресурсы, а в RSHUTDOWN — освободить их. PHP-модуль для Pinba использует обе эти фазы. В RINIT он инициализируется, в RSHUTDOWN — вычисляет, сколько ресурсов было потрачено на обработку запроса, а затем все данные отсылаются UDP-пакетом на Pinba-сервер.
Отправка UDP-пакета на C осуществляется достаточно быстро, поэтому модуль Pinba не добавляет в PHP-процесс дополнительной нагрузки. А за счет того, что Pinba работает в виде модуля, то достаточно установить и настроить его, и вы сразу же, без внесения изменений в PHP-код, сможете узнать такие параметры вашей системы, как количество запросов на каждый из скриптов, среднее время работы и многое другое.
К сожалению, если у вас сложная система, общих параметров будет недостаточно.
Изначально в первой версии Pinba (назовем её Pinba v0.1) не было таймеров. Эта версия могла сказать нам, как часто вызывается тот или иной скрипт, каково среднее время ответа, каков средний размер ответа в байтах и тому подобное. Нельзя было узнать частоту запросов к MySQL, memcached или другим сервисам. Вам может показаться это не столь критичным, но в нашей системе помимо MySQL и memcached используется еще с десяток различных сервисов, написанных на C/C++.
Если в системе появлялась проблема (например, что-то начинало «тормозить»), то Pinba v0.1 показывала нам, что проблема есть, но не всегда можно было быстро понять, в чем именно она заключается. Чаще всего в таких ситуациях виновным был какой-то из сервисов, к которому PHP делал запросы (MySQL, memcached и другие).
Чтобы научиться находить такие проблемные места быстро, в следующей версии Pinba были введены таймеры.
Фактически мы решили замерять время работы вызовов mysql_connect / mysql_query / memcache_connect и т.п., отсылать это время на Pinba-сервер и строить отчёты по таймерам. На псевдо-PHP-коде это выглядит примерно так:
Здесь мы замеряем время работы вызова mysql_connect и привзязываем к таймеру 2 тега, по которым впоследствии сможем строить отчёты.
Все таймеры вместе со всеми данными отсылаются на Pinba-сервер и там по ним строятся отчётные таблицы. Это позволяет увидеть, какие операции занимают больше всего времени в данный момент. Более того, если у вас, например, сотни MySQL-серверов и тормозит только один из них, Pinba позволяет легко вычислить тот самый проблемный сервер благодаря очень гибкой схеме отчётов по таймерам.
Вот список таблиц, к которым Pinba дает доступ:
Условно все таблицы можно разделить на 2 типа: таблицы с «сырыми» данными и отчёты.
Есть 4 таблицы с «сырыми» данными: request, tag, timer, timertag. Эти таблицы содержат запись о каждом вызове скрипта, таймера и тега за последние несколько минут. В высоконагруженных системах, эти таблицы могут содержать миллионы записей, поэтому мы не рекомендуем их использовать напрямую. Вместо этого лучше использовать таблицы-отчёты, которые содержат достаточно полезных данных для анализа производительности системы.
Report_by_script_name — один из наиболее используемых отчётов; содержит информацию о том, как часто вызывался каждый скрипт, среднее время его выполнения, использование им CPU, количество приходящегося на него трафика.
Поля с суффиксом _total — это сумма соответствующих значений для всех запросов за последние 5 минут. То есть, например, req_time_total — это сумма времени выполнения всех запросов для соответствующего скрипта за последние 5 минут. А req_time_total/req_count — среднее время выполнения скрипта. Поля req_utime_* и req_stime_* показывают использование CPU в user mode и system mode соответственно.
В нашей компании по этим данным мы строим графики количества запросов к тому или иному скрипту и графики потребления CPU скриптами (графики 1, 2):
График 1.
График 2.
Report_by_hostname: данный отчёт показывает, сколько всего запросов идет на конкретный сервер. Он имеет почти такой же список полей, но вместо поля script_name таблица содержит поле hostname.
Наверное, некоторые ожидали увидеть в переменной hostname домен, переданный в HTTP-заголовке Host. Но на самом деле hostname — это содержимое переменной $_ENV['HOSTNAME'] и содержит имя машины.
Основная суть этого отчёта — получение информации о количестве запросов на конкретный сервер и о том, не идет ли на какие-то сервера больше запросов, чем на соседние.
Report_by_server_name: в этом отчёте данные сгруппированы по домену, на который пришел запрос. Он показывает количество запросов, идущих на тот или иной домен. Структура таблицы такая же, как у предыдущих двух, только данные теперь сгруппированы по полю server_name.
Report_by_status: этот отчёт используется для просмотра HTTP-статусов, с которыми завершаются наши скрипты:
Если в отчёте есть статус 500, то значит, что у нас где-то происходят «Fatal error» в PHP-коде.
Отчёты, рассмотренные выше, полезны для общего анализа системы. Но для более детального анализа мы используем таймеры и теги.
Таймер — это время исполнения какого-то участка кода. К таймеру можно привязать несколько тегов. Тег имеет ключ и значение. Например, в коде таймера, который был показан выше,
мы замеряем время выполнения функции mysql_connect и привязываем 2 тега — group и host.
По умолчанию в Pinba нет никаких отчётов о таймерах и тегах, но она дает очень гибкие возможности по их созданию. Ниже рассмотрим подробнее, как это сделано в Badoo.
В первую очередь мы используем таймеры для получения статистики запросов к различным источникам данных: MySQL, memcached, сервисам, написанным на C/C++. Все такие запросы мы «обернули» Pinba-таймерами с двумя тегами: group и host (host — это адрес базы или сервиса, group — это операция над сервисом).
Итак, если мы внедрили в нашу систему тег, который отсылается в Pinba, мы можем построить несколько отчётов. Прежде всего это будет полный отчёт по всем значениям тега. В нашем примере с тегом group мы можем построить отчёт о том, как часто вызывается та или иная операция и сколько времени (суммарно) на неё уходит. Для этого нужно создать таблицу:
Имя таблицы произвольное и ни на что не влияет. Важно, чтобы порядок полей был именно таким, как в примере, а также значения для ENGINE и COMMENT='tag_info:group'. В комментарии group — это имя тега, по которому мы создаем отчёт. А tag_info — это тип отчёта (есть еще tag_report, речь о котором пойдет ниже).
После создания таблицы Рinba автоматически начнет вносить туда данные. Этот отчёт будет иметь примерно такой вид:
Например, из этого отчёта видно, что у нас есть какие-то очень медленные curl_request.
Отчеты типа tag_info дают общую картину по его использованию в системе. Чтобы более детально изучить, откуда вызываются те или иные операции, нужно построить такой же отчёт, но с группировкой по имени скрипта. Для этого в Pinba нужно создать такую таблицу:
Структура таблицы во многом похожа на предыдущий отчёт tag_info_group. Обратите внимание на то, что появилось поле script_name, и в поле COMMENT мы создали отчёт типа tag_report. Из этой таблицы мы можем получить все те же данные, что и из предыдущей, но сгруппированные по script_name.
Можно посмотреть, какие операции выполняются в том или ином скрипте:
В этом примере показана разница между полями hit_count и req_count. Req_count — это число HTTP-запросов, во время обработки которых хотя бы один раз был вызван таймер с указанным tag_value. Hit_count — сколько раз всего был вызван таймер с указанным tag_value.
В примере выше видно, что в нашем скрипте /admin/messages/all.phtml в среднем 30 раз вызывается memcache_get. Скорее всего это ошибка программиста, и страница нуждается в оптимизации.
Если у вас много серверов баз данных, memcached и других сервисов, то возможны случаи, когда «тормозит» только один сервер. И его «торможение» на общем фоне может быть не очевидным. Для этих целей мы сделали еще один тег с именем server. Для него можно создать общий отчёт tag_info:server и посмотреть общую статистику для каждого хоста. Вот пример данных для memcached-статистики:
Общий отчёт по тегу host недостаточно информативен. Он показывает частоту вызова таймеров с тем или иным хостом, но без информации о производимых операциях. К счастью, Pinba умеет создавать отчёты типа tag_info и tag_report с группировкой по 2 тегам:
Данный отчёт позволяет получить статистику операций над каждым хостом. Например, можно посмотреть статистику операций на определенном хосте:
По понятным причинам, именно SELECT занимают большую часть времени.
Также, например, можно сравнить статистику для одной и той же операции на разных хостах. Пример для memcache_connect:
Ещё можно сделать отчёт типа tag2_report, в котором информация по 2 тегам разбита по скриптам:
Приведем пример, где эта таблица может быть полезной. В нашей системе все пользователи распределены между сотнями MySQL-серверов. Это называется «шардинг». Также есть определенные центральные MySQL-сервера для специфических задач. В теории все веб-скрипты должны делать запросы только на «шарды» и не делать запросы на центральные базы. Hostname наших «шардов» начинается на dbs* или dbb*. Проверить, есть ли скрипты, делающие коннекты на другие MySQL-сервера, можно вот таким запросом:
Он покажет какие скрипты делают запросы на центральные базы данных.
Но даже всего этого нам оказалось недостаточно. Когда клиент шлёт нам HTTP-запрос, то последний сначала попадает в nginx и далее проксируется в PHP. Что будет, если PHP-процесс в этот момент не может принять и обработать запрос? Например, если сервер перегружен, или в следствие сетевых проблем nginx не сможет связаться с php-fpm процессом? Пользователь в этом случае увидит ошибку, а мы в PHP о ней не узнаем (правда, она будет в логах nginx).
Для того, чтобы иметь представление о том, какие ответы (какие HTTP-статусы) мы возвращаем клиенту, разработчик Pinba Антон Довгаль сделал модуль для nginx. Модуль для nginx работает также, как и PHP-модуль, но по понятным причинам не имеет таймеров. Наиболее полезные отчёты, которые он делает — report_by_script_and_status и report_by_status.
Pinba хранит данные за последние несколько минут. Это время можно поменять в настройках. Но этого недостаточно, если вы хотите следить за тем, как со временем меняется производительность системы. Для этого нужно хранить данные отчётов Pinba (не обязательно всех) за продолжительное время и строить по ним графики. Таким образом можно наблюдать динамику изменения нагрузки на системы и на отдельные ее скрипты, а также отслеживать, как ваш PHP-код нагружает базы, memcached и другие источники данных.
Pinba не умеет строить графики и хранить данные за долгий период. Для этого нужно использовать отдельные утилиты. Можно настроить Zabbix, чтобы он мониторил Pinba и строил графики по каким-то её значениям. Можно использовать кольцевые (циклические) базы данных типа RRDtool или Graphite. В нашей компании мы используем RRDtool.
RRDtool не описать в двух словах. У него много своих нюансов, и у разных людей разные предпочтения в построении графиков, поэтому эта тема достойна отдельной статьи. В интернете уже достаточно руководств, которые помогут вам с нуля начать работу с этим набором утилит.
Что же нам дала Pinba? Большинство проблем производительности стали выявляться намного быстрее, чем до её внедрения. Если какой-то скрипт стал намного чаще запрашиваться пользователями, он легко может быть найден в Pinba. Если вдруг какой-то из сервисов (MySQL, memcached и т.п.) стал медленней работать, то при наличии правильных отчётов в Pinba можно легко локализовать этот сервис. А если он стал «тормозить» из-за высокой частоты запроса, то благодаря Pinba иногда можно локализовать скрипты, часто запрашивающие конкретный проблемный сервис.
Очень полезно смотреть графики Pinba после выкладки новой версии кода на сервера. Можно увидеть, как поменялась нагрузка на систему. Но для этого важно продумать, какие графики будут строиться.
Однако не стоит воспринимать Pinba как замену полноценному мониторингу серверов. Мы, например, используем Zabbix для мониторинга потребления CPU, памяти, дисков и сетевой активности на всех серверах. С другой стороны, есть Pinba с графиками в RRD. Сопоставляя графики из этих двух систем, можно легко посчитать «стоимость» PHP-запроса и оценить, сколько запросов в секунду способны обработать ваши сервера. А это, в свою очередь, позволяет спланировать, нужны ли закупки новых серверов в ближайшее время или же есть возможности для оптимизации кода.
Не считая PHP-модуля, Pinba никак не завязана на PHP и может использоваться для мониторинга систем, написанных на других языках. На GitHub уже есть проекты по использованию Pinba в Python и Ruby.
Максим max_m Матюхин, разработчик
компания Badoo
Со временем число серверов будет расти, и рано или поздно вы зададитесь вопросами
«А что сейчас вообще происходит с системой? Как часто выполняется тот или иной скрипт и как долго? Какие операции занимают большую часть времени?» Системы мониторинга типа Zabbix дают лишь общую, поверхностную картину состояния приложения.
Чтобы получить ответы на эти вопросы, в Badoo был разработан сервиc мониторинга и статистики в реальном времени — Pinba. В данной статье мы расскажем о нашем опыте использования его для мониторинга и профайлинга нашей системы.
Пару слов о Badoo
Чтобы оценить уровень сложности задачи, опишем в нескольких словах, что представляет из себя Badoo. На сегодняшний день у нас функционируют 2 дата-центра, один — в Америке, второй — в Европе. В дата-центрах установлены сотни PHP-серверов, MySQL-серверов, десятки memcached и «самописных» сервисов, написанных на C/C++. Внутри Badoo существуют свои подпроекты (например, веб-сайт, приложения для мобильных устройств и рабочих столов), реализация и характер нагрузок на которые сильно различаются. В одном PHP-запросе могут происходить взаимодействия с десятками различных источников данных (база, кеш, сервис). Это плохо для производительности, но необходимо для решения поставленных бизнес-задач. И вдобавок к этому мы выкладываем новый код от 2 до 5 раз в неделю. Мониторинг производительности такой системы — непростая задача. Pinba помогла решить большой пласт проблем, связанных с мониторингом производительности PHP-скриптов. Данный сервис собирает информацию обо всех обработанных PHP-запросах и формирует подробные отчёты по этим данным.
Как всё работает
На Хабрахабре уже была статья о том, как начать работать с Pinba: «Pinba — мониторим php в реальном времени». В ней автор описал, как установить и настроить Pinba, поэтому сейчас мы сконцентрируемся на более интересных вещах: как это всё работает и какую информацию можно получить.
Общая схема работы с Pinba отображена на диаграмме:
Pinba состоит из PHP-модуля (англ. PHP extension) и сервера. Модуль Pinba автоматически шлёт данные обо всех обработанных запросах на сервер. Pinba-сервер — это сервис, написанный на С, который:
- собирает по протоколу UDP данные об обработанных запросах;
- хранит все эти данные в памяти и строит по ним отчёты;
- предоставляет доступ к сырым данным и отчётам по протоколу MySQL, то есть фактически является MySQL engine.
Чтобы узнать, что происходит с системой в данный момент, достаточно соединиться с сервером любым MySQL-клиентом и сделать несколько запросов из таблиц-отчётов. Например, можно посмотреть статистику по запросам на каждый из PHP-скриптов (один из наиболее используемых отчётов в Pinba):
mysql> SELECT * FROM report_by_script_name;
Ниже мы подробнее опишем, как работать с отчётами в Pinba.
Как работает PHP-модуль для Pinba
Еще на этапе планирования первой версии сервиса Pinba сразу же возникла идея организации сбора общей статистики без внесения изменений в PHP-код. Люди, имеющие опыт написания PHP-модулей, знают, что последние имеют возможность выполнять некоторые действия перед каждым запросом (фаза PHP_RINIT) и после его обработки (фаза PHP_RSHUTDOWN). Например, в фазе PHP_RINIT модуль может инициализировать свои внутренние ресурсы, а в RSHUTDOWN — освободить их. PHP-модуль для Pinba использует обе эти фазы. В RINIT он инициализируется, в RSHUTDOWN — вычисляет, сколько ресурсов было потрачено на обработку запроса, а затем все данные отсылаются UDP-пакетом на Pinba-сервер.
Отправка UDP-пакета на C осуществляется достаточно быстро, поэтому модуль Pinba не добавляет в PHP-процесс дополнительной нагрузки. А за счет того, что Pinba работает в виде модуля, то достаточно установить и настроить его, и вы сразу же, без внесения изменений в PHP-код, сможете узнать такие параметры вашей системы, как количество запросов на каждый из скриптов, среднее время работы и многое другое.
К сожалению, если у вас сложная система, общих параметров будет недостаточно.
Таймеры
Изначально в первой версии Pinba (назовем её Pinba v0.1) не было таймеров. Эта версия могла сказать нам, как часто вызывается тот или иной скрипт, каково среднее время ответа, каков средний размер ответа в байтах и тому подобное. Нельзя было узнать частоту запросов к MySQL, memcached или другим сервисам. Вам может показаться это не столь критичным, но в нашей системе помимо MySQL и memcached используется еще с десяток различных сервисов, написанных на C/C++.
Если в системе появлялась проблема (например, что-то начинало «тормозить»), то Pinba v0.1 показывала нам, что проблема есть, но не всегда можно было быстро понять, в чем именно она заключается. Чаще всего в таких ситуациях виновным был какой-то из сервисов, к которому PHP делал запросы (MySQL, memcached и другие).
Чтобы научиться находить такие проблемные места быстро, в следующей версии Pinba были введены таймеры.
Фактически мы решили замерять время работы вызовов mysql_connect / mysql_query / memcache_connect и т.п., отсылать это время на Pinba-сервер и строить отчёты по таймерам. На псевдо-PHP-коде это выглядит примерно так:
pinba_timer_start(array('type'=>'db::connect', 'host'=>'users.sql'));
$conn = mysql_connect(...);
pinba_timer_stop();
Здесь мы замеряем время работы вызова mysql_connect и привзязываем к таймеру 2 тега, по которым впоследствии сможем строить отчёты.
Все таймеры вместе со всеми данными отсылаются на Pinba-сервер и там по ним строятся отчётные таблицы. Это позволяет увидеть, какие операции занимают больше всего времени в данный момент. Более того, если у вас, например, сотни MySQL-серверов и тормозит только один из них, Pinba позволяет легко вычислить тот самый проблемный сервер благодаря очень гибкой схеме отчётов по таймерам.
Начинаем работать с таблицами
Вот список таблиц, к которым Pinba дает доступ:
mysql> SHOW TABLES FROM pinba;
+--------------------------------------+
| Tables_in_pinba |
+--------------------------------------+
| info |
| report_by_hostname |
| report_by_hostname_and_script |
| report_by_hostname_and_server |
| report_by_hostname_server_and_script |
| report_by_script_name |
| report_by_server_and_script |
| report_by_server_name |
| report_by_status |
| request |
| tag |
| timer |
| timertag |
+--------------------------------------+
13 rows in set (0.00 sec)
Условно все таблицы можно разделить на 2 типа: таблицы с «сырыми» данными и отчёты.
Есть 4 таблицы с «сырыми» данными: request, tag, timer, timertag. Эти таблицы содержат запись о каждом вызове скрипта, таймера и тега за последние несколько минут. В высоконагруженных системах, эти таблицы могут содержать миллионы записей, поэтому мы не рекомендуем их использовать напрямую. Вместо этого лучше использовать таблицы-отчёты, которые содержат достаточно полезных данных для анализа производительности системы.
Таблицы отчётов
Report_by_script_name — один из наиболее используемых отчётов; содержит информацию о том, как часто вызывался каждый скрипт, среднее время его выполнения, использование им CPU, количество приходящегося на него трафика.
mysql> DESC report_by_script_name;
+------------------+--------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+------------------+--------------+------+-----+---------+-------+
| req_count | int(11) | YES | | NULL | |
| req_per_sec | float | YES | | NULL | |
| req_time_total | float | YES | | NULL | |
| req_time_percent | float | YES | | NULL | |
| req_time_per_sec | float | YES | | NULL | |
| ru_utime_total | float | YES | | NULL | |
| ru_utime_percent | float | YES | | NULL | |
| ru_utime_per_sec | float | YES | | NULL | |
| ru_stime_total | float | YES | | NULL | |
| ru_stime_percent | float | YES | | NULL | |
| ru_stime_per_sec | float | YES | | NULL | |
| traffic_total | float | YES | | NULL | |
| traffic_percent | float | YES | | NULL | |
| traffic_per_sec | float | YES | | NULL | |
| script_name | varchar(128) | YES | | NULL | |
+------------------+--------------+------+-----+---------+-------+
15 rows in set (0.00 sec)
Поля с суффиксом _total — это сумма соответствующих значений для всех запросов за последние 5 минут. То есть, например, req_time_total — это сумма времени выполнения всех запросов для соответствующего скрипта за последние 5 минут. А req_time_total/req_count — среднее время выполнения скрипта. Поля req_utime_* и req_stime_* показывают использование CPU в user mode и system mode соответственно.
В нашей компании по этим данным мы строим графики количества запросов к тому или иному скрипту и графики потребления CPU скриптами (графики 1, 2):
График 1.
График 2.
Report_by_hostname: данный отчёт показывает, сколько всего запросов идет на конкретный сервер. Он имеет почти такой же список полей, но вместо поля script_name таблица содержит поле hostname.
mysql> DESC report_by_hostname;
+------------------+-------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+------------------+-------------+------+-----+---------+-------+
| req_count | int(11) | YES | | NULL | |
.........
| hostname | varchar(32) | YES | | NULL | |
+------------------+-------------+------+-----+---------+-------+
15 rows in set (0.00 sec)
Наверное, некоторые ожидали увидеть в переменной hostname домен, переданный в HTTP-заголовке Host. Но на самом деле hostname — это содержимое переменной $_ENV['HOSTNAME'] и содержит имя машины.
Основная суть этого отчёта — получение информации о количестве запросов на конкретный сервер и о том, не идет ли на какие-то сервера больше запросов, чем на соседние.
Report_by_server_name: в этом отчёте данные сгруппированы по домену, на который пришел запрос. Он показывает количество запросов, идущих на тот или иной домен. Структура таблицы такая же, как у предыдущих двух, только данные теперь сгруппированы по полю server_name.
Report_by_status: этот отчёт используется для просмотра HTTP-статусов, с которыми завершаются наши скрипты:
mysql> SELECT req_count, status FROM report_by_status;
+-----------+--------+
| req_count | status |
+-----------+--------+
| 540622 | 200 |
| 2578 | 301 |
| 21955 | 302 |
| 296 | 403 |
| 2090 | 404 |
+-----------+--------+
5 rows in set (0.14 sec)
Если в отчёте есть статус 500, то значит, что у нас где-то происходят «Fatal error» в PHP-коде.
Таймеры и теги
Отчёты, рассмотренные выше, полезны для общего анализа системы. Но для более детального анализа мы используем таймеры и теги.
Таймер — это время исполнения какого-то участка кода. К таймеру можно привязать несколько тегов. Тег имеет ключ и значение. Например, в коде таймера, который был показан выше,
pinba_timer_start(array('group'=>'db::connect', 'host'=>'users.sql'));
$conn = mysql_connect(...);
pinba_timer_stop();
мы замеряем время выполнения функции mysql_connect и привязываем 2 тега — group и host.
По умолчанию в Pinba нет никаких отчётов о таймерах и тегах, но она дает очень гибкие возможности по их созданию. Ниже рассмотрим подробнее, как это сделано в Badoo.
В первую очередь мы используем таймеры для получения статистики запросов к различным источникам данных: MySQL, memcached, сервисам, написанным на C/C++. Все такие запросы мы «обернули» Pinba-таймерами с двумя тегами: group и host (host — это адрес базы или сервиса, group — это операция над сервисом).
Итак, если мы внедрили в нашу систему тег, который отсылается в Pinba, мы можем построить несколько отчётов. Прежде всего это будет полный отчёт по всем значениям тега. В нашем примере с тегом group мы можем построить отчёт о том, как часто вызывается та или иная операция и сколько времени (суммарно) на неё уходит. Для этого нужно создать таблицу:
CREATE TABLE `tag_info_group` (
`tag_value` varchar(64) DEFAULT NULL,
`req_count` int(11) DEFAULT NULL,
`req_per_sec` float DEFAULT NULL,
`hit_count` int(11) DEFAULT NULL,
`hit_per_sec` float DEFAULT NULL,
`timer_value` float DEFAULT NULL
) ENGINE=PINBA DEFAULT CHARSET=latin1 COMMENT='tag_info:group'
Имя таблицы произвольное и ни на что не влияет. Важно, чтобы порядок полей был именно таким, как в примере, а также значения для ENGINE и COMMENT='tag_info:group'. В комментарии group — это имя тега, по которому мы создаем отчёт. А tag_info — это тип отчёта (есть еще tag_report, речь о котором пойдет ниже).
После создания таблицы Рinba автоматически начнет вносить туда данные. Этот отчёт будет иметь примерно такой вид:
mysql> SELECT * FROM tag_info_group ORDER BY timer_value;
+--------------------+-----------+-------------+-----------+-------------+-------------+
| tag_value | req_count | req_per_sec | hit_count | hit_per_sec | timer_value |
+--------------------+-----------+-------------+-----------+-------------+-------------+
| curl_request | 56216 | 281.08 | 56710 | 283.55 | 11977.3 |
| memcache_get | 2563499 | 12817.5 | 11462991 | 57315 | 6823.04 |
| hsc_connect | 2319186 | 11595.9 | 2870366 | 14351.8 | 6140.5 |
| hsc_open_index | 2319158 | 11595.8 | 3285335 | 16426.7 | 5805.61 |
| hsc_select | 2312567 | 11562.8 | 3158465 | 15792.3 | 5778.57 |
| memcache_connect | 2563064 | 12815.3 | 4007451 | 20037.3 | 2389.65 |
| memcache_set | 917102 | 4585.51 | 1616016 | 8080.08 | 1059.08 |
| memcache_delete | 600720 | 3003.6 | 2451872 | 12259.4 | 785.702 |
| scribe_receive | 382881 | 1914.41 | 975892 | 4879.46 | 382.522 |
| hsc_update | 84877 | 424.385 | 85287 | 426.435 | 317.637 |
| hsc_insert | 41564 | 207.82 | 41574 | 207.87 | 280.468 |
| scribe_send | 382894 | 1914.47 | 975892 | 4879.46 | 174.156 |
| memcache_increment | 60817 | 304.085 | 88734 | 443.67 | 30.9102 |
| memcache_add | 14818 | 74.09 | 16281 | 81.405 | 4.71686 |
| memcache_multi_get | 2543 | 12.715 | 2543 | 12.715 | 1.59621 |
| hsc_delete | 4 | 0.02 | 9 | 0.045 | 0.003373 |
+--------------------+-----------+-------------+-----------+-------------+-------------+
16 rows in set (0.00 sec)
Например, из этого отчёта видно, что у нас есть какие-то очень медленные curl_request.
Отчеты типа tag_info дают общую картину по его использованию в системе. Чтобы более детально изучить, откуда вызываются те или иные операции, нужно построить такой же отчёт, но с группировкой по имени скрипта. Для этого в Pinba нужно создать такую таблицу:
CREATE TABLE `tag_report_group` (
`script_name` varchar(128) DEFAULT NULL,
`tag_value` varchar(64) DEFAULT NULL,
`req_count` int(11) DEFAULT NULL,
`req_per_sec` float DEFAULT NULL,
`hit_count` int(11) DEFAULT NULL,
`hit_per_sec` float DEFAULT NULL,
`timer_value` float DEFAULT NULL
) ENGINE=PINBA DEFAULT CHARSET=latin1 COMMENT='tag_report:group'
Структура таблицы во многом похожа на предыдущий отчёт tag_info_group. Обратите внимание на то, что появилось поле script_name, и в поле COMMENT мы создали отчёт типа tag_report. Из этой таблицы мы можем получить все те же данные, что и из предыдущей, но сгруппированные по script_name.
Можно посмотреть, какие операции выполняются в том или ином скрипте:
mysql> SELECT tag_value, req_count, hit_count, timer_value, hit_count/req_count FROM tag_report_group WHERE script_name='/admin/messages/all.phtml' ORDER BY timer_value DESC;
+--------------------+-----------+-----------+-------------+---------------------+
| tag_value | req_count | hit_count | timer_value | hit_count/req_count |
+--------------------+-----------+-----------+-------------+---------------------+
| memcache_get | 107439 | 3227537 | 1060.68 | 30.0406 |
| memcache_connect | 107439 | 887789 | 270.919 | 8.2632 |
| scribe_receive | 107573 | 283478 | 68.9106 | 2.6352 |
| memcache_set | 34339 | 153080 | 50.6079 | 4.4579 |
| scribe_send | 107573 | 283478 | 39.7583 | 2.6352 |
| memcache_delete | 18236 | 21306 | 4.54436 | 1.1683 |
| curl_request | 15 | 15 | 0.514396 | 1.0000 |
| memcache_decrement | 1250 | 1250 | 0.251141 | 1.0000 |
| memcache_multi_get | 125 | 125 | 0.066473 | 1.0000 |
| memcache_increment | 2 | 2 | 0.000336 | 1.0000 |
+--------------------+-----------+-----------+-------------+---------------------+
10 rows in set (0.03 sec)
В этом примере показана разница между полями hit_count и req_count. Req_count — это число HTTP-запросов, во время обработки которых хотя бы один раз был вызван таймер с указанным tag_value. Hit_count — сколько раз всего был вызван таймер с указанным tag_value.
В примере выше видно, что в нашем скрипте /admin/messages/all.phtml в среднем 30 раз вызывается memcache_get. Скорее всего это ошибка программиста, и страница нуждается в оптимизации.
Если у вас много серверов баз данных, memcached и других сервисов, то возможны случаи, когда «тормозит» только один сервер. И его «торможение» на общем фоне может быть не очевидным. Для этих целей мы сделали еще один тег с именем server. Для него можно создать общий отчёт tag_info:server и посмотреть общую статистику для каждого хоста. Вот пример данных для memcached-статистики:
mysql> SELECT * FROM tag_info_server WHERE tag_value LIKE 'memcache%' ORDER BY timer_value;
+------------------+-----------+-------------+-----------+-------------+-------------+
| tag_value | req_count | req_per_sec | hit_count | hit_per_sec | timer_value |
+------------------+-----------+-------------+-----------+-------------+-------------+
| memcached7.mlan | 350702 | 1753.51 | 1767513 | 8837.57 | 781.644 |
| memcached3.mlan | 336217 | 1681.08 | 1734430 | 8672.15 | 871.633 |
| memcached1.mlan | 350082 | 1750.41 | 1823910 | 9119.55 | 883.52 |
| memcached8.mlan | 357798 | 1788.99 | 1793808 | 8969.04 | 908.848 |
| memcached10.mlan | 343287 | 1716.44 | 1757085 | 8785.42 | 909.042 |
| memcached5.mlan | 398042 | 1990.21 | 1861729 | 9308.64 | 914.772 |
| memcached4.mlan | 401584 | 2007.92 | 1877775 | 9388.88 | 937.53 |
| memcached2.mlan | 459912 | 2299.56 | 2028406 | 10142 | 971.189 |
| memcached6.mlan | 399768 | 1998.84 | 1912571 | 9562.86 | 975.094 |
| memcached9.mlan | 425276 | 2126.38 | 1939575 | 9697.88 | 1008.29 |
+------------------+-----------+-------------+-----------+-------------+-------------+
10 rows in set (0.00 sec)
Общий отчёт по тегу host недостаточно информативен. Он показывает частоту вызова таймеров с тем или иным хостом, но без информации о производимых операциях. К счастью, Pinba умеет создавать отчёты типа tag_info и tag_report с группировкой по 2 тегам:
CREATE TABLE `tag_info_group_server` (
`group_value` varchar(64) DEFAULT NULL,
`server_value` varchar(64) DEFAULT NULL,
`req_count` int(11) DEFAULT NULL,
`req_per_sec` float DEFAULT NULL,
`hit_count` int(11) DEFAULT NULL,
`hit_per_sec` float DEFAULT NULL,
`timer_value` float DEFAULT NULL
) ENGINE=PINBA DEFAULT CHARSET=latin1 COMMENT='tag2_info:group,server'
Данный отчёт позволяет получить статистику операций над каждым хостом. Например, можно посмотреть статистику операций на определенном хосте:
mysql> SELECT * FROM tag_info_group_server WHERE server_value = 'dbs101.mlan' ORDER BY timer_value;
+-------------+--------------+-----------+-------------+-----------+-------------+-------------+
| group_value | server_value | req_count | req_per_sec | hit_count | hit_per_sec | timer_value |
+-------------+--------------+-----------+-------------+-----------+-------------+-------------+
| db::replace | dbs101.mlan | 154 | 0.77 | 154 | 0.77 | 0.257526 |
| db::delete | dbs101.mlan | 1340 | 6.7 | 1340 | 6.7 | 1.84398 |
| db::begin | dbs101.mlan | 6437 | 32.185 | 6589 | 32.945 | 2.96375 |
| db::commit | dbs101.mlan | 6437 | 32.185 | 6589 | 32.945 | 3.04067 |
| db::insert | dbs101.mlan | 4674 | 23.37 | 11171 | 55.855 | 13.9457 |
| db::update | dbs101.mlan | 6358 | 31.79 | 10399 | 51.995 | 18.197 |
| db::connect | dbs101.mlan | 16826 | 84.13 | 16826 | 84.13 | 22.1383 |
| db::select | dbs101.mlan | 14372 | 71.86 | 47106 | 235.53 | 180.235 |
+-------------+--------------+-----------+-------------+-----------+-------------+-------------+
8 rows in set (0.01 sec)
По понятным причинам, именно SELECT занимают большую часть времени.
Также, например, можно сравнить статистику для одной и той же операции на разных хостах. Пример для memcache_connect:
mysql> SELECT server_value, req_count, hit_count, timer_value FROM tag_info_group_server WHERE group_value='memcache_connect' ORDER BY timer_value;
+------------------+-----------+-----------+-------------+
| server_value | req_count | hit_count | timer_value |
+------------------+-----------+-----------+-------------+
| memcached1.mlan | 366138 | 365061 | 191.808 |
| memcached3.mlan | 354688 | 353760 | 192.184 |
| memcached10.mlan | 365358 | 364341 | 197.353 |
| memcached8.mlan | 368912 | 367839 | 213.768 |
| memcached7.mlan | 374160 | 373152 | 215.914 |
| memcached5.mlan | 415444 | 414434 | 217.855 |
| memcached4.mlan | 423394 | 422242 | 252.416 |
| memcached2.mlan | 478949 | 477641 | 272.346 |
| memcached6.mlan | 414088 | 413003 | 279.038 |
| memcached9.mlan | 441589 | 440481 | 377.952 |
+------------------+-----------+-----------+-------------+
10 rows in set (0.01 sec)
Ещё можно сделать отчёт типа tag2_report, в котором информация по 2 тегам разбита по скриптам:
CREATE TABLE `tag_report_group_server` (
`sc0зript_name` varchar(128) DEFAULT NULL,
`tag1_value` varchar(64) DEFAULT NULL,
`tag2_value` varchar(64) DEFAULT NULL,
`req_count` int(11) DEFAULT NULL,
`req_per_sec` float DEFAULT NULL,
`hit_count` int(11) DEFAULT NULL,
`hit_per_sec` float DEFAULT NULL,
`timer_value` float DEFAULT NULL
) ENGINE=PINBA DEFAULT CHARSET=latin1 COMMENT='tag2_report:group,server'
Приведем пример, где эта таблица может быть полезной. В нашей системе все пользователи распределены между сотнями MySQL-серверов. Это называется «шардинг». Также есть определенные центральные MySQL-сервера для специфических задач. В теории все веб-скрипты должны делать запросы только на «шарды» и не делать запросы на центральные базы. Hostname наших «шардов» начинается на dbs* или dbb*. Проверить, есть ли скрипты, делающие коннекты на другие MySQL-сервера, можно вот таким запросом:
mysql> SELECT * FROM tag_report_group_server WHERE tag1_value='db::connect' AND tag2_value NOT LIKE 'dbs%' AND tag2_value NOT LIKE 'dbb%';
Он покажет какие скрипты делают запросы на центральные базы данных.
nginx + Pinba
Но даже всего этого нам оказалось недостаточно. Когда клиент шлёт нам HTTP-запрос, то последний сначала попадает в nginx и далее проксируется в PHP. Что будет, если PHP-процесс в этот момент не может принять и обработать запрос? Например, если сервер перегружен, или в следствие сетевых проблем nginx не сможет связаться с php-fpm процессом? Пользователь в этом случае увидит ошибку, а мы в PHP о ней не узнаем (правда, она будет в логах nginx).
Для того, чтобы иметь представление о том, какие ответы (какие HTTP-статусы) мы возвращаем клиенту, разработчик Pinba Антон Довгаль сделал модуль для nginx. Модуль для nginx работает также, как и PHP-модуль, но по понятным причинам не имеет таймеров. Наиболее полезные отчёты, которые он делает — report_by_script_and_status и report_by_status.
Построение графиков
Pinba хранит данные за последние несколько минут. Это время можно поменять в настройках. Но этого недостаточно, если вы хотите следить за тем, как со временем меняется производительность системы. Для этого нужно хранить данные отчётов Pinba (не обязательно всех) за продолжительное время и строить по ним графики. Таким образом можно наблюдать динамику изменения нагрузки на системы и на отдельные ее скрипты, а также отслеживать, как ваш PHP-код нагружает базы, memcached и другие источники данных.
Pinba не умеет строить графики и хранить данные за долгий период. Для этого нужно использовать отдельные утилиты. Можно настроить Zabbix, чтобы он мониторил Pinba и строил графики по каким-то её значениям. Можно использовать кольцевые (циклические) базы данных типа RRDtool или Graphite. В нашей компании мы используем RRDtool.
RRDtool не описать в двух словах. У него много своих нюансов, и у разных людей разные предпочтения в построении графиков, поэтому эта тема достойна отдельной статьи. В интернете уже достаточно руководств, которые помогут вам с нуля начать работу с этим набором утилит.
Результаты
Что же нам дала Pinba? Большинство проблем производительности стали выявляться намного быстрее, чем до её внедрения. Если какой-то скрипт стал намного чаще запрашиваться пользователями, он легко может быть найден в Pinba. Если вдруг какой-то из сервисов (MySQL, memcached и т.п.) стал медленней работать, то при наличии правильных отчётов в Pinba можно легко локализовать этот сервис. А если он стал «тормозить» из-за высокой частоты запроса, то благодаря Pinba иногда можно локализовать скрипты, часто запрашивающие конкретный проблемный сервис.
Очень полезно смотреть графики Pinba после выкладки новой версии кода на сервера. Можно увидеть, как поменялась нагрузка на систему. Но для этого важно продумать, какие графики будут строиться.
Однако не стоит воспринимать Pinba как замену полноценному мониторингу серверов. Мы, например, используем Zabbix для мониторинга потребления CPU, памяти, дисков и сетевой активности на всех серверах. С другой стороны, есть Pinba с графиками в RRD. Сопоставляя графики из этих двух систем, можно легко посчитать «стоимость» PHP-запроса и оценить, сколько запросов в секунду способны обработать ваши сервера. А это, в свою очередь, позволяет спланировать, нужны ли закупки новых серверов в ближайшее время или же есть возможности для оптимизации кода.
Не считая PHP-модуля, Pinba никак не завязана на PHP и может использоваться для мониторинга систем, написанных на других языках. На GitHub уже есть проекты по использованию Pinba в Python и Ruby.
Максим max_m Матюхин, разработчик
компания Badoo
Полезные ссылки
- Официальная страница проекта Pinba
- Pinba Engine development list — англоязычная Google-группа для обсуждения Pinba
- Pinba Engine development list (in Russian) — русскоязычная Google-группа для обсуждения Pinba
- Pinba — мониторим php в реальном времени — статья на Хабрахабре о первых шагах с Pinba
- Официальная страница проекта RRDtool
- Официальная страница проекта Graphite
- Циклическая база данных — wikipedia.org
- Nginx module for pinba
- Python WSGI middleware for pinba