Всем привет! Я Артём Седых, работаю ведущим разработчиком команды банковского сопровождения. Проекту уже девятый год, накопилась большая функциональная база и много легаси‑кода с набором узких мест для возможной оптимизации. В наборе статей рассказываю о нашем опыте разработки и внедрения собственной системы мониторинга бэкенда PHP с возможностью просмотреть, как именно проседают экшены, и даже попытаться спрогнозировать поведение. Если не читали предыдущую часть — ссылка выше. Сегодня в продолжение предыдущей статьи рассмотрим оставшуюся архитектурную часть — о некоторых методах сбора метрик производительности и месте для хранения. Остальной же материал будет посвящен самому интересному — получившимся дашбордам Grafana. Каждый дашборд сопровождается конкретными примерами, какие проблемы удалось обнаружить и какие рекомендации по оптимизации получаем с каждого элемента. Не буду томить, впереди много картинок, поехали!
Отправка метрик
В прошлой части определились с конкретными метриками, разработали и внедрили механизм сбора. Теперь возникает вопрос: как можно без боли отправить данные в хранилище? Попробовали несколько подходов, у каждого свои плюсы и минусы, вылилось в несколько вариаций SDK.
В самом базовом случае — отправлять метрики сразу напрямую из живого процесса в базу данных. Это не быстро, рискуем нарваться на недоступность БД, тратится время на подключение и открытие коннекта.
Самым быстрым решением будет файловая система — время записи в районе нескольких мс. Можно использовать запись в pipe‑файл и читать из него параллельно работающим демоном, который будет кешировать и отправлять логи в хранилище в своем темпе. Но и возможные места для сбоев расширяются: за демоном и трубой нужно следить. Также получаем состояние гонки при параллельном выполнении запросов, которое решается различными методами блокировки.
Вариант без демона — выбираем папку, в которой будем писать в рандомный свободный файл, не забывая о блокировках. Файл наполняется до нужного объема (например, 1 МБ), писателю туда запрещается писать, и такой файл обрабатывает воркер‑читатель, массово загружая строки с метриками в хранилище. Здесь встречаемся с проблемами файловой системы, может не хватить места, параллельные процессы повлекут состояние гонки и задержат отправку, файлы могут пропасть или повредиться.
Третий вариант — использовать сервис, специально предназначенный для сбора статистики, например Open Telemetry Collector. Поддерживается передача по протоколам gRPC либо HTTP с использованием формата protobuf. Перестаем волноваться насчет параллельных запросов, пусть волнуется коллектор. Легко сконфигурировать одним файлом: настроить входящие потоки, методы обработки, выходящие потоки. Жертвуем же тем, что библиотека коллектора требует свои форматы для передачи, нужно создать Trace / Log / Metric и наполнить атрибутами, инициализировать сетевые функции и направить сетевой запрос. В этом варианте добавляются возможные проблемы с сетью и время на передачу данных. Зато получаем довольно стабильную передачу метрик без суеты с файлами и параллельными запросами. Остановились на этом варианте.
Из альтернатив можно также рассмотреть отправку в рэббит, или кэшсервис типа redis, откуда воркер растащит по нужным местам. Это всё еще сетевой запрос, и дополнительно понадобится воркер. Как видим, способов много и точек оптимизации еще больше. Итого держим три разных варианта SDK, каждая команда может решить и выбрать, какой метод подходит именно им (а можно взять SDK в качестве примера и реализовать свой вариант).
Хранение
Метрики собрали, куда складывать?
Для задач мониторинга и анализа используют формулировку OLAP (Online Analytical Processing). OLAP — технология, позволяющая в режиме реального времени получить определенный срез данных для их последующего анализа. Такие БД и инструменты специально оптимизированы под задачи сбора, хранения и выборки метрик — в основном это временные ряды, их довольно выгодно хранить в столбцовом формате. Из столбцовых СУБД наиболее подходит ClickHouse (см отличительные преимущества).
Оптимальная массовая вставка данных, поддержка индексов, агрегатных функций и фильтров. Интеграция с open telemetry collector (ссылка), есть плагин для Grafana и — самый важный для нашей команды аргумент — поддержка языка SQL. Все разработчики бэкенда знакомы с его синтаксисом, можно строить наши графики и отчеты как обычные SQL‑запросы, поддерживаются CTE (Common Table Expressions), фильтры сортировка — и всё в привычном синтаксисе. Клик предлагает богатый набор агрегатных функций, что сильно помогло при разработке дашбордов.
Завели таблицу в ClickHouse с ENGINE = MergeTree и составным индексом по environment+start_datetime. Настроили интеграцию между SDK, сервисом otel collector и связали с ClickHouse. Метрики с живого проекта полетели в БД.
Интересно, сколько в итоге наши данные занимают места? Заглянем в графану, за последний месяц собрали такие показатели (в среднем 60 запросов в минуту).
Большая часть объема занимает метрика parameters, т. к. это JSON с лимитом в 1 024 символа. Если не логировать параметры, счет будет идти на десятки мегабайт в месяц, что впечатляет и увеличивает шансы на доступность использования в высоконагруженных сервисах. Также в ClickHouse можно задать Time to live как на строки, так и на отдельные колонки. В нашем случае очищаем значения parameters и data спустя 1 месяц с помощью TTL — исследование параметров актуально в момент анализа текущей оптимизации и не так важно в далекой перспективе.
Визуализация и алерты
Где проводить мониторинг и анализ? Grafana победила безальтернативно: имеет все нужные возможности, уже используется в компании, есть плагин для ClickHouse. Grafana предоставляет множество инструментов: легко разрабатывать графики и дашборды, поддерживаются time series, столбчатые диаграммы, диаграммы состояния и многое другое.
Заготовленные дашборды можно легко экспортировать в JSON, хранить в том же репозиториии импортировать в ручном либо автоматическом режиме, используя provisioning. Огромный плюс — поддерживаются алерты с гибкой настройкой триггеров и направлений для рассылки.
Примеры дашбордов Grafana
Мониторинг внедрили, инструменты подключили, настало время поделиться, какие панели получились и какую полезную информацию можно извлечь при анализе. Располагая таким небольшим, но богатым набором метрик в логах, можно построить множество аналитических графиков и отчетов. Плагин ClickHouse для Grafana и синтаксис SQL максимально гибко позволяют подойти к решению данной задачи.
Каждый дашборд использует стандартный фильтр графаны – период выборки справа вверху. Слева вверху – основные фильтры (где это применимо): среда, тег, контроллер, экшен, активная роль.
Анализ экшенов
Выполняется без агрегации (кроме диаграммы ошибок) – видно показатели по каждому запросу.
Отображение сырых данных. Графики детализации по экшенам полезны при анализе производительности конкретных экшенов по времени и в сравнении с другими. Для лучшей четкости картинки можно открыть в новой вкладке.
Рассмотрим пример получения информации по заявке. Виден пик в восемь секунд, по памяти всё нормально, а вот на количестве SQL‑запросов уже видно, что именно заняло 8 секунд: навели курсор — получили результат — экшен выполнил 10 419 SQL‑запросов, что, очевидно, не самый эффективный способ доставать кучу данных из БД. Скорее всего, внутри используются запросы в цикле, которые можно оптимизировать, переделав на один запрос, и не тратить кучу времени на инфраструктурные задержки обслуживания каждого из 10 тысяч запросов.
В конце — квинтэссенция всех наших трудов по сбору дополнительных метрик: благодаря тому, что мы замеряем общее время на обращения к ресурсам в формате Duration, можно их содержимое отобразить в красивом графике, на котором видно, что конкретно заняло и сколько времени. Посмотрим поближе.
Мини-профайлер
График по секундам: сколько ушло на запросы к БД, сколько на внешние запросы и оставшееся время выполнения кода (пометим как cpu_time). При добавлении еще метрик типа Duration разбивка будет еще точнее.
По сути, у нас вышел мини-профайлер, очень пригодились колонки со счетчиками. Видим, что тот 8-секундный запрос как раз ждал результатов из БД 10 тысяч запросов, занял целых 6 секунд (помечено синим как sql_time) и 2 секунды на обработку данных в коде (зеленым как cpu_time), также для ресурса внешних систем (желтый external_time). Получаем наглядное отображение составляющих по времени для каждого запроса: сразу видим слабыеместа — куда целиться при оптимизации. В Grafana используется панель типа Time series с опцией Stack series = Normal.
Пример запроса для построения данного графика:
SELECT
start_datetime AS time,
controller_name || '.' || action_name,
duration_sql_s AS sql_time,
duration_external_request_s AS external_time,
duration_s - duration_sql_s - duration_external_request_s AS cpu_time
FROM logs
WHERE $__timeFilter(start_datetime)
AND environment = '${environment}'
AND ('all' = '${tag}' OR action_group_tag = '${tag}')
AND ('all' = '${controller}' OR controller_name = '${controller}')
AND ('all' = '${action}' OR action_name = '${action}')
AND ('-1' = toString(${active_role}) OR active_role = toString(${active_role}))
ORDER BY time;Благодаря поддержке SQL в ClickHouse очень просто получается разрабатывать подобные графики, работаем как с обычными таблицами в том же Postgres. Есть несколько макросов, один из них $__timeFilter — туда подставляется фильтр по времени из графаны. Его и другие фильтры из шапки дашборда располагаем в секции WHERE. Фильтр по роли дает возможность смотреть, насколько сильно отличается быстродействие в системе для разных ролей пользователей.
Нагрузка на систему
В предыдущем дашборде сложно будет развернуться, если количество экшенов достигает 1 000. Сложно отследить каждый — повесим систему при выборке и отображении большого набора данных. Поэтому разработан дашборд с группировкой по тегам (группам экшенов) — мониторинг состояния системы, а также обнаружение критичных точек. Слева в виде графиков, агрегация sum/max/avg покажет динамику по тегам, справа — в основном экстремумы max в виде диаграммы состояния (если красное — значение отклоняется от заданного порога threshold). Для поиска экстремумов также могут подойти p95/p99.
Агрегированные данные по интервалам, длительность интервала можно настроить в параметрах дашборда.
Здесьможем обнаружить, что тег провисает по определенному признаку, а потом отправиться в другие дашборды для подробного изучения и найти виновный экшен.
Фактически получаем суперспособность видеть систему насквозь! На указанном примере уже накопилось с десяток задач под оптимизацию узких мест:
Время обработки (median) — 30 секунд на экспорт данных в Excel (его же видно на графике «Время выполнения БД avg» — сразу знаем какой‑то медленный SQL‑запрос попался в экспорте).
Количество SQL‑запросов (max) — под 90 тысяч при интеграции и 60 тысяч при сохранении. Запросы в цикле, требующие группировку.
ошибок — 25% файлов не удалось скачать или загрузить в 08:50 — проблемы с ФС?
Время выполнения БД (max) — неудовлетворительное время на запросы к БД в экшенах получения списка (70 секунд при наведении мышкой), а получение списка сущностей — одна из важнейших операций при работе с системой: нужно ускорять.
Количество исх. запросов (sum) — видно, в какие периоды проявляют активность интеграционные запросы. Стоит присмотреться: если будет аномальное поведение, регулировать доступ к внешним системам по API.
Время ожидания исх. запросов (max) — а вот и аномалии, если слева могла естественным образом накопиться сумма (например, много мелких запросов), то справа каждая красная секция показывает 160 секунд ожидания внешних систем! Нужно разобраться, а что такого тяжелого передают друг другу сервисы, и стоит рассмотреть переход на асинхронную обработку запросов.
Потребление памяти (avg) — в среднем 125 MB потреблял экшен типа export в 8:40, пока бить тревогу не стоит, но можно и оптимизировать.
Потребление памяти (max) — а вот и экстремумы, в лидерах export и integration показывают >600 MB, однозначно стоит заняться оптимизацией потребления памяти, как только обнаружим конкретный экшен по другим дашбордам, зная провисающий тег.
Потребление памяти (sum) покажет, если много экшенов выполняются одновременно и суммарно могут до отвала загрузить память в короткий промежуток времени. Пока в пределах нормы.
Таблицы ТОП по метрикам
Возможность мониторить состояние системы — это круто, однако не всегда получится держать руку на пульсе и следить, чтобы не выскочил конкретный показатель в красную зону. Можем пойти дальше — попросить БД с помощью SQL и сделать готовые таблички с конкретными экшенами, которые провисают по определенным критериям. Отсюда вышла идея создания дашборда ТОПов экшенов по метрикам — готовые таблицы экшенов для оптимизации и другая полезная информация. Узнать больше о влиянии конкретных экшенов на работоспособность системы в самых разных аспектах. В Grafana это всё строится на стандартной таблице с разными настройками по колонкам (единицы измерения, state gauge, thresholds).
Группировка за выбранный период и сортировка по максимальной метрике, чтобы показать TOP_count записей.
Есть колонка diff — разница с показателем данной метрики в данном экшене за предыдущий период, а также переменная diff_gap — на сколько интервалов назад смотрим, чтобы вычислить diff. Интервал — время между «от» и «до», настроенные справа. Пример — если дашборд настроен на последние сутки, желательно посмотреть разницу, как экшен вел себя те же сутки, но неделю назад (т. е. diff_gap=7).
Составили множество ТОПов по самым разнообразным аспектам, разделили на секции.
Секция «Нагрузка»
ТОПы общей нагрузки по системе. Анализируется метрика длительности duration_s и количество запросов с количеством ошибок.
Это те же экстремумы с прошлого дашборда, но уже без группировки по тегам – видно каждый экшен в удобном списочном формате. Видно, какой экшен больше всего вызывали, что больше всего вернуло ошибки, каждый экстремум по длительности и медиану по длительности.
Внизу — какие экшены больше всего заняли времени сервиса. Используется сумма — сочетание частоты вызова экшена и его общего времени работы. Получается список самых критичных экшенов, которые в целом влияют на производительность всей системы и больше всего затормаживают работу всех пользователей.
Последняя — таблица по самым активным пользователям, сколько конкретный пользователь занял системных ресурсов своей активностью. Сумма по общему времени всех его запросов и сумма по их количеству. Если встретим некую ненормальную активность от пользователя, стоит обратить внимание: возможно, он парсит данные или пытается DDoSить. Но также это может быть юзер, который работает с самыми тяжелыми сущностями и экшенами, и стоит к его проблемам отнестись с особой важностью, вылечить его боли. В текущем примере топ-1 — нормальное поведение, работает интеграционный юзер для контроля данных, передаваемых по интеграции.
Секция «БД»
Аналогичным образом эта секция ТОПов посвящена базе данных. На каждую метрику типа Duration (количество и длительность операций) получится сделать такую секцию.
Выделяющиеся значения по количеству SQL‑запросов, скорее всего, требуют оптимизации, переход на BULK SELECT / INSERT / UPDATE, а экстремумы по длительности — оптимизации самих SQL‑запросов. Настройка показателей thresholds в графане позволяет раскрашивать Table Gauge в яркие цвета — когда стоит обратить внимание и подумать об оптимизации. Если не задать thresholds, графана раскрасит в подходящие цвета исходя из самих данных.
Внизу результаты ТОПов по мини‑профайлеру относительно суммарной длительности именно SQL‑запросов. Используется сумма — сколько заняли SQL‑запросы в целом за период по системе, и выбираются самые тяжелые экшены с дальнейшим раскрытием на составляющие. Отображается количество запросов и процентовка, на что потратили время, т. е. собрали всю статистику по мини‑профайлеру с первого дашборда и составили табличку с конкретными показателями самых тяжелых относительно времени базы данных, заодно со статистикой по другим составляющим и по количеству запросов. payment.list особенно необходимо оптимизировать: 3 часа в день крутились запросы БД, обрабатывающие этот экшен, также его было видно и в секции общей нагрузки.
Секция RAM
Секция, посвященная оценке потребления памяти. Слева max, справа медиана — наиболее влияющие на RAM экшены. Третьей идет экспериментальная таблица, попробовали подсчитать, сколько экшен занимает памяти в секунду, чтобы не мешал другим экшенам. Здесь, естественно, информация не точная, мы работаем с метрикой «макс. потребление памяти», а ведь память можно быстро занять и быстро освободить, а потом крутить еще минуту, но обычно экшен всё же занимает память и долгое время не отпускает. 250 МБ в секунду — однозначно стоит присмотреться к методам оптимизации использования RAM, особенно исходя из того, что он же на первом месте в четвертой таблице, — сколько экшен отобрал памяти за весь период суммарно.
Секция CPU
Покажет самые тяжелые экшены с точки зрения времени на оставшийся код помимо БД и HTTP‑запросов — обычно это и есть выполнение кода, неэффективные алгоритмы, лишние проверки, преобразования. Отслеживаем максимальное и медианное время, также наибольшее суммарное время CPU экшена с разбивкой по остальным %.
История разбора и оптимизации кейса с прода
Пришел алерт на высокое потребление CPU.
С помощью ТОПов легко узнать, что именно вызывает нагрузку, уже в общей н��грузке видно виновников — запрос на удаление файлов по интеграции и запрос на обновление статуса документов.
Они же и отобразились в нижней таблице «ТОП по времени CPU (sum)».
Отсюда можно понять, что наибольший вклад в нагрузку процессора вызвал аномальный рост вызова метода doc.update — 17 часов времени CPU в сутки! С 89% — это приговор для процессора.
В результате анализа выяснилось, что методы действительно оказались связаны, и по одному из типов документов вызывалось обновление во время каждого вызова removedoc, а сам update вызывал кучу другого кода для пересчета наборов данных, связанных с конкретным документом. Решили внедрить кеширование статуса документов на микросервисе, чтобы не было обновления каждый раз, а статус обновлялся массово.
Вывели на прод и пронаблюдали моментальное снижение количества вызовов doc.update — заметно на графике дашборда «Нагрузки на систему»: теги integration и other шли стык в стык, а с 17:40 запросы тега other существенно сократились.
Секция «Обращения к внешним системам»
Все таблицы аналогично секции БД. Видно, все медленные и часто запрашиваемые интеграционные запросы.
Большое количество запросов в одном экшене (savecontracts, uploaddoc), возможно, нуждается в объединении (если позволяет API) или разделении в рамках самих экшенов (по n вызовов на каждый набор), тем самым получим больше контроля и стабильное время интеграционной составляющей.
Большая суммарная длительность запросов может говорить о тяжелых требованиях к внешним системам, стоит заняться частотой запросов и объемом запрашиваемых данных (например, с помощью разбивки большого потока на составляющие).
Любые интеграционные запросы в обычных (пользовательских) действиях могут быть чувствительными точками замедления работы. Не заставлять пользователей висеть в браузере и синхронно ждать ответа внешних систем, над которыми у нас меньше контроля. Такие экшены внимательно изучать и контролировать, а еще лучше — переносить интеграцию на асинхронное взаимодействие, где это возможно.
Конец второй части
Сегодня завершили технологическую часть и прошлись по основным разработанным дашбордам графаны. Это основной костяк, через который быстро и просто получается узнать об узких местах системы и поставить задачи на оптимизацию. Через неделю в третьей (заключительной) части рассмотрим применение со стороны devops на дашбордах SLI/Apdex, поколдуем над статистическими методами для прогноза снижения производительности, немного про автоматические уведомления, перспективы развития, и в заключении сравнительный анализ выбранного подхода и выводы в целом о нашем опыте.
Пока же в комментариях предлагаю поделиться впечатлениями по теме, очень приветствуются свои истории медленных и тяжелых запросов, расскажите, как решали проблемы производительности на проектах? Какие инструменты используете, какие мысли по поводу выбранного здесь подхода? Есть ли метрики, которые особенно хотелось бы отслеживать у себя? Какие дашборды могли бы ещё пригодиться? Большое спасибо за внимание! Жду вас в следующий четверг на заключительной части =)