Проблема
API стал получать всё больше и больше нагрузки, необходимо было проводить анализ работы, и после оптимизировать работу большого backend'а. Обычно процесс оптимизации типичного backend'а на php включает:
оптимизации SQL-запросов в БД;
оптимизации работы с кэшем (повышение hitrate, увеличение объёма кэшируемых данных);
оптимизация внутренних процессов в backend (вынесение тяжёлых процессов в асинхронный режим, оптимизация внутренних структур данных)
Всё это уже было проведено, но не давало достаточного эффекта - API был большим, в нём было много сервисов с разной логикой, сложностью и связями. Точечные улучшения давали эффект, но было желание посмотреть на весь backend сверху - оценить потоки данных, оценить создаваемую нагрузку на каждый из внешних хранилищ (БД, кэш, сервисы) и оптимизировать исходя из полученных данных.
Уже существующие реализации APM (newrelic, datadog, elastic apm agent, dynatrace, open tracing) были рассмотрены, но не были выбраны так как подразумевалось подключать в проект внешние расширения php, покупать лицензию и/или поднимать в инфраструктуре дополнительные узлы.
Соглашусь, что для целей APM больше подходит не анализ логов, а отдельное хранилище с агрегированными данными - метриками, на основе которых и будут строится графики - это быстрее, дольше живёт (по периоду доступ к данным) и вообще правильнее. Однако мониторинг реализовывался поступательно, в течение нескольких месяцев, шаг за шагом меняя акценты в данных, без каких-либо изменений инфраструктуры. Отчасти это был ещё и эксперимент: насколько удачно может быть мониторинг на логах минимальными усилиями.
Решение
Решено было использовать логи приложения из nginx и сервера приложения (php-fpm в данном случае), отправляемые в loki, для складирования агрегированной информации по запросам-ответам, которые потому будут агрегированы grafana+loki и по которым будут построены графики.
В плане:
Меняем формат логов nginx и php-fpm - добавлен вывод дополнительных полей и меняем формат на json;
Это довольно просто: всё берётся из документации: подправляется формат с помощью log_format и access.format соответственно.Добавляем логгирование подключения и выполнения запросов/команд с таймингом - к БД и кэшу в приложении
Это было не сложно, ведь используемый фреймворк позволяет переопределить базовые классы для команд и запросов. Реализация очень зависит от фреймворка, но чаще всего заключается в переопределении базовых классов взаимодействия (pdo, cache) с простыми$dbConnectionTime += $start_connection_time - microtime(true).Оборачиваем все вызовы внешних сервисов в прокладку (названную коннектором), которая считает время обращения, выполняет валидацию (в том числе и структуры) ответа и логгирует успешность вызова;
Это было даже полезно, ведь теперь у нас все обращения к внешним системам (а их уже около 15) единообразно выполняются, валидируются и логгируются.
Формат логов nginx и приложения
Логи nginx выглядят довольно просто:
{
"body_bytes_sent": "3186",
"client_ip": "10.***.***.***",
"client_req_id": "cad148c1-****-4819-****-035a4a9ace14",
"connection": "10186566",
"http_user_agent": "***",
"pid": "16",
"request_method": "POST",
"request_time": "0.102",
"request_uri": "/***/***/***?***=***",
"request_uri_path": "/***/***/***",
"status": "200",
"time_local": "10/Apr/2023:23:27:15 +0300",
"upstream_connect_time": "0.000",
"upstream_header_time": "0.101",
"upstream_response_time": "0.101",
"uri": "/index.php"
}Настройки nginx
// общие
http {
// ...
log_format json_upstream_logs escape=json '{"time_local":"$time_local","client_req_id":"$client_req_id","client_ip":"$client_ip","request_method":"$request_method","request_uri":"$request_uri","request_uri_path":"$request_uri_path","status":"$status","body_bytes_sent":"$body_bytes_sent","http_user_agent":"$http_user_agent","request_time":"$request_time","uri":"$uri","upstream_connect_time":"$upstream_connect_time","upstream_header_time":"$upstream_header_time","upstream_response_time":"$upstream_response_time","pid":"$pid","connection":"$connection"}';
// ...
map $request_uri $request_uri_path {
"~^(?P<path>[^?]*)(\?.*)?$" $path;
}
}
// сервера
server {
#Определение идентификатора запроса. если его нет в запросе - создаём
if ($arg_client_req_id !~ $arg_client_req_id) {
set $client_req_id $request_id;
}
if ($arg_request_id) {
set $client_req_id $arg_request_id;
}
if ($arg_client_req_id) {
set $client_req_id $arg_client_req_id;
}
#Определение ip адреса клиента
# запросы приходят с проксирующего сервера, так что HTTP-заголовки приходят доверенные
if ($http_x_real_ip !~ $http_x_real_ip) {
set $client_ip $remote_addr;
}
if ($http_x_real_ip) {
set $client_ip $http_x_real_ip;
}
location ~ ^/index\.php$ {
// ..
access_log /var/log/nginx/access.log json_upstream_logs;
// ..
}
}Заменённые логи php-fpm выглядят тоже довольно просто:
{
"C": "43.21",
"M": "2097152",
"P": "9",
"Q": "",
"R": "-",
"RequestId": "f894d70d5910***3772a94261f7c40ca",
"T": "20/Apr/2023:16:17:19 +0300",
"d": "0.023",
"f": "/var/www/html/web//index.php",
"l": "42",
"m": "POST",
"n": "www",
"p": "17",
"q": "",
"r": "/index.php",
"s": "200",
"t": "20/Apr/2023:16:17:19 +0300",
"u": ""
}Настройки php-fpm
access.format = '{"RequestId":"%{REQUEST_ID}e","C":"%C","d":"%d","f":"%f","l":"%l","m":"%m","M":"%M","n":"%n","P":"%P","p":"%p","q":"%q","Q":"%Q","r":"%r","R":"%R","s":"%s","T":"%T","t":"%t","u":"%u"}'Тайминги в приложении
Ко всем логам из приложения добавляем мета-информацию (для возможности трассировки логов между разными сервисами):
id запроса;
вызываемый сервис;
id авторизованного пользователя, сессия;
Вначале оборачиваем всё: коннекты/выполнение запросов к БД, коннекты/выполнение команд в кэше, считаем время/объём данных.
Из получаемых данных формируем первую категорую сообщений - timings, о ходе выполнения запроса. Формируется по одному сообщению на каждый запрос в конце выполнения:
{
"cacheCommands": 14,
"cacheCommandsTime": 0.005800008773803711,
"cacheConnectionTime": 0.0006201267242431641,
"cacheReads": 7,
"cacheReadsSize": 7989,
"cacheWrites": 4,
"cacheWritesSize": 1480,
"dbConnectionTime": 0.0017120838165283203,
"dbQueries": 5,
"dbQueriesTime": 0.0563662052154541,
"externalCalls": 1,
"externalCallsTime": 0.03611111640930176
}Вызовы внешних сервисов
Об успешности и времени выполнения запросов к внешним сервисам формируем вторую категория - external_calls - на каждый вызов по сообщению в логе.
В случае успешного вызова:
{
"requestTime": 0.03611111640930176,
"requestUrl": "http://10.***.***.***/***/***/***/***",
"systemId": "***"
}В случае ошибки вызова:
{
"error": "cURL error 28: Connection timeout after 1001 ms (see https://curl.haxx.se/libcurl/c/libcurl-errors.html): 0",
"request":
{
"body": "",
"url": "http://***.***.***:8280/***/***/***?***=***"
},
"requestTime": 1.0022687911987305,
"response": null,
"systemId": "***"
}Визуализация
Далее остаётся лишь вооружиться logql, графаной и написать запросы верные к хранилищу.
Заводим две переменные, которые выбираются в обоих дашбордах (таким образом реализована смена исследуемого контура):
$nginx_source - logql-селектор для логов nginx
$fpm_source - logql-селектор для логов php-fpm
Весь APM поделён на две дашборды:
Performance Status. Для оценки "насколько всё хорошо справляется".
Remote Calls. Для изучения взаимодействия с другими сервисами.
Performance Status
Состоит из следующих блоков:
Статистика ответов API в разрезе отдельных сервисов/кодов ответа.
RPS. Счётчик запросов ко всему API, с разделением по кодам ответа nginx.
-
Summary for {code}. Выбираем из выпадающего списка grafana любые коды ответа, на основе которых будет построены:
Average Response time (nginx / fpm).
Response time. Перцентили ответов по данным nginx.
Response count by path for {code}. Количество ответов по сервисам для выбранного кода ответа.
Response size by path. Средний размер ответа сервисов.
Response time by path. Среднее время ответа сервисов.
Как выглядит
Как формируется
{{status}}: sum by (status) (rate($nginx_source | json | error != "JSONParserErr"[1s]))
Как формируется
avg by nginx - {{status}} |
|
connect_time - {{status}} |
|
header_time - {{status}} |
|
response_time - {{status}} |
|
avg by php-fpm - {{s}} |
|
Как формируется
max by nginx - {{status}} |
|
95% by nginx - {{status}} |
|
90% by nginx - {{status}} |
|
70% by nginx - {{status}} |
|
50% by nginx - {{status}} |
|
30% by nginx - {{status}} |
|
Как формируется
{{request_uri_path}}: sum by (request_uri_path) (rate($nginx_source | json | __error__ != "JSONParserErr" | status=$http_code [1s]))
Как формируется
{{request_uri_path}}: avg_over_time($nginx_source | json | __error__ != "JSONParserErr" | unwrap body_bytes_sent | __error__=""[1s]) by (request_uri_path)
Как формируется
{{request_uri_path}}: avg_over_time($nginx_source | json | __error__ != "JSONParserErr" | unwrap request_time | __error__=""[1s]) by (request_uri_path)
Сводная статистика приложения в разрезе отдельных хранилищ (по данным fpm).
DB/cache/calls summary. Траты времени приложением на разные активности: на работу с БД, кэшем и другими сервисами.
queries and commands. Количество запросов, чтений/записей из кэша.
cache size. Объём считанных/записанных данных в кэш.
External calls summary. Распределение времени работы с внешними сервисами.
Как выглядит
Как формируется
connect to db time |
|
db queries time |
|
connect to cache time |
|
cache time |
|
external calls time |
|
Как формируется
db queries |
|
cache commands |
|
cache reads |
|
cache writes |
|
Как формируется
read from cache |
|
write to cache |
|
Как формируется
{{request_uri_path}}: avg_over_time($fpm_source |=`:"external_calls"` | json | __error__ != "JSONParserErr" | unwrap message_requestTime | __error__=""[1s]) by (message_systemId)
Статистика работы с БД в разрезе отдельных сервисов.
DB time. Время работы с БД среднее.
DB queries count. Среднее количество запросов к БД.
Как выглядит
Как формируется
{{request_uri_path}}: avg_over_time($fpm_source |=`:"timings"` | json | __error__ != "JSONParserErr" | unwrap message_dbQueriesTime | __error__=""[1s]) by (method)
Как формируется
{{request_uri_path}}: avg_over_time($fpm_source |=`:"timings"` | json | __error__ != "JSONParserErr" | unwrap message_dbQueries | __error__=""[1s]) by (method)
Статистика работы с кэшем в разрезе отдельных сервисов.
Cache commands time. Среднее время работы с кэшем.
Cache commands count. Среднее количество команд к кэшу.
Cache writes size. Средний размер записи в кэш.
Cache reads size. Средний размер записи в кэш.
Как выглядит
Как формируется
{{request_uri_path}}: avg_over_time($fpm_source |=`:"timings"` | json | __error__ != "JSONParserErr" | unwrap message_cacheCommandsTime | __error__=""[1s]) by (method)
Как формируется
{{request_uri_path}}: avg_over_time($fpm_source |=`:"timings"` | json | __error__ != "JSONParserErr" | unwrap message_cacheCommands | __error__=""[1s]) by (method)
Как формируется
{{request_uri_path}}: quantile_over_time(0.9, $fpm_source |=`:"timings"` | json | __error__ != "JSONParserErr" | unwrap message_cacheWritesSize | __error__=""[1s]) by (method)
Как формируется
{{request_uri_path}}: quantile_over_time(0.9, $fpm_source |=`:"timings"` | json | __error__ != "JSONParserErr" | unwrap message_cacheReadsSize | __error__=""[1s]) by (method)
Статистика работы с другими API в разрезе отдельных сервисов.
External calls time. Время работы с внешними сервисами.
Как выглядит
Как формируется
{{request_uri_path}}: avg_over_time($fpm_source |=`:"timings"` | json | __error__ != "JSONParserErr" | unwrap message_externalCallsTime | __error__=""[1s]) by (method)
Утилизация CPU и памяти воркерами.
PHP avg memory & CPU.
Как выглядит
Как формируется
php cpu cons. % - {{s}} |
|
php mem cons. - {{s}} |
|
Нестандартные логи nginx / fpm.
nginx messages. Все сообщения из nginx, не являющиеся access-логами.
php-fpm messages. То же самое, только для php.
Как выглядит
Как формируется
логи nginx |
|
логи php-fpm |
|
Сводка по исключениям приложения.
Exceptions. Все строки из логов приложения, в которых есть Exception.
Exceptions messages. Детально строки логов с Exceptions, чтобы изучить прямо на месте.
Как выглядит
Как формируется
{{category}}: sum by (category) (rate($fpm_source |=`Exception` | json | __error__ != "JSONParserErr" [1s]))
External calls
Состоит из изменяемого количества блоков, каждый из которых содержит сводку по взаимодействию с одним внешним сервисом, в который обращается монолит.
-
График RPS & avg. time + ошибок. График, который показывает:
Количество успешных ответов от сервиса.
Среднее и максимальное время ответа сервиса.
Ошибки (с группировкой по типу) при обращении к сервису, при парсинге ответа, при анализе ответа.
Логи обращения к сервису. Отображаются списком все обращения в обратном хронологическом порядке.
Как выглядит
Как формируется
Успешные запросы |
{{message_systemId}} |
|
Неуспешные запросы |
errored - {{message_systemId}} : {{message_error}} |
|
Среднее время выполнения |
avg request time - {{message_systemId}} |
|
Максимальное время выполнения |
max request time - {{message_systemId}} |
|
Как формируется
$fpm_source |=`external_calls` |=`systemId":"$external_system` | json | __error__ != "JSONParserErr" | line_format "{{.timestamp}}: {{ printf "%s" .message_requestTime }} {{ .message_error }}"
Выводы
Построить свой APM из подручных средств получилось.
У него есть минусы:
Малый срок хранения данных; заполняем и без того тяжёлое хранилище логов метриками;
Медленная агрегация данных;
Необходимо вручную менять конфигурации либо переопределять (встраиваться) в работу с БД/кэшем/внешними сервисами.
Также стоит не забывать о "скрытых" обращениях к внешним хранилищам: разного рода библиотеки для интеграций (s3, oauth2.0), которые ходят во внешние системы и на которые тоже стоило бы повесить мониторинг. Например, у нас на обращение к oauth2 серверу данных тоже висит мониторинг (да ещё и запрос проксируется с двухкратным ретраем) - пришлось только отнаследовать пару базовых классов библиотеки и добавить логгирование данных.
Все минусы, кроме последнего, можно нивелировать, перейдя на другое хранилище или уже готовую реализацию APM.
Есть и плюсы:
Всё работает на текущем установленном софте; Не нужно ничего нового устанавливать.
При изучении пользовательских проблем (особенно жалоб на большое время ответа) можно сразу же, не отходя от логов бизнес-логики проверить и тайминги выполнения разного рода обращений;
Например, зачастую проблемы медленного API у нас появлялись именно из-за долгих обращений к внешним сервисам. Благодаря установке nginx-прокси перед этими сервисами мы уменьшили сетевые издержки.При разработке можно сразу же по логам контейнера оценить сложность создаваемого сервиса - видно сколько раз он сходил в БД, в кэш, сколько выполнил запросов и какие из них были тяжелее остальных;