golang

Дело о несрабатывающем тайм-ауте

  • суббота, 12 апреля 2025 г. в 00:00:10
https://habr.com/ru/companies/ozontech/articles/896890/

Привет! Меня зовут Олег Стрекаловский, я старший разработчик в команде корзины маркетплейса. Сервис корзины Ozon отвечает за хранение корзин покупателей и за отрисовку соответствующего экрана в приложении и на сайте. Слежение за стабильностью сервиса — важная задача. В этой статье я расскажу о нюансах интерпретации данных, которые предоставляет система мониторинга Prometheus. Если вы тоже часто всматриваетесь в графики, чтобы понять, как чувствует себя сервис, эта статья для вас.

С чего всё началось

Все сервисы Ozon строятся на базе общей платформы. Новый сервис создаётся в пару кликов — и разработчик сразу получает набор инструментов для наблюдения за ним: просмотр логов, трассировка запросов и подсчет метрик. API сервиса, как и клиенты к другим gRPC-сервисам, автоматически инструментируется. Это позволяет единообразно собирать стандартные метрики типа RPS, response time, error rate без дополнительных усилий и добавлять их на дашборд сервиса в Grafana.

Чтобы отрисовать экран корзины, наш сервис обращается к десятку других, обогащая свои данные ценами, остатками на складах и прочим.

Как-то, анализируя время ответов этих сервисов в Grafana, мы заметили, что 99-й перцентиль response time (далее — RT) успешных ответов сервиса X существенно превышает установленный нами тайм-аут для запроса. Он был равен 20 мс, но на графиках этот перцентиль почти всегда был больше. График RT выглядел так:

Мы убедились, что тайм-аут применяется в точке вызова внешнего сервиса. Результаты анализа кода и трейсов подтвердили, что тайм-аут для запросов установлен. При этом метрики неуспешных запросов, куда попали бы запросы, превысившие тайм-аут, были равны 0.

Устройство гистограмм и подсчёт перцентилей

Известно, что при создании гистограммы нужно задать некие бакеты. Их размеры в платформенной библиотеке Ozon были следующими: 1 мс, 5 мс, 15 мс, 50 мс, 100 мс, 250 мс, 500 мс, 750 мс, 1 с, 1,5 с, 2 с, 3,5 с, 5 с. Prometheus сам обходит поды для сбора метрик, которые отдаются по отдельным URL в текстовом формате.

Снимаем с одного из подов нашего сервиса данные гистограммы успешных gRPC-запросов, которую для нас автоматически создаёт платформа:

ozon_external_service_response_time_seconds_bucket{external_service="X",method="Xmethod",status="ok",le="0.001"} 0
ozon_external_service_response_time_seconds_bucket{external_service="X",method="Xmethod",status="ok",le="0.005"} 5523
ozon_external_service_response_time_seconds_bucket{external_service="X",method="Xmethod",status="ok",le="0.015"} 9999
ozon_external_service_response_time_seconds_bucket{external_service="X",method="Xmethod",status="ok",le="0.05"} 10155
ozon_external_service_response_time_seconds_bucket{external_service="X",method="Xmethod",status="ok",le="0.1"} 10155
ozon_external_service_response_time_seconds_bucket{external_service="X",method="Xmethod",status="ok",le="0.25"} 10155
ozon_external_service_response_time_seconds_bucket{external_service="X",method="Xmethod",status="ok",le="0.5"} 10155
ozon_external_service_response_time_seconds_bucket{external_service="X",method="Xmethod",status="ok",le="0.75"} 10155
ozon_external_service_response_time_seconds_bucket{external_service="X",method="Xmethod",status="ok",le="1"} 10155
ozon_external_service_response_time_seconds_bucket{external_service="X",method="Xmethod",status="ok",le="1.5"} 10155
ozon_external_service_response_time_seconds_bucket{external_service="X",method="Xmethod",status="ok",le="2"} 10155
ozon_external_service_response_time_seconds_bucket{external_service="X",method="Xmethod",status="ok",le="3.5"} 10155
ozon_external_service_response_time_seconds_bucket{external_service="X",method="Xmethod",status="ok",le="5"} 10155
ozon_external_service_response_time_seconds_bucket{external_service="X",method="Xmethod",status="ok",le="+Inf"} 10155
ozon_external_service_response_time_seconds_sum{external_service="X",method="Xmethod",status="ok"} 57.148873807000165
ozon_external_service_response_time_seconds_count{external_service="X",method="Xmethod",status="ok"} 10155

Каждая строка с суффиксом _bucket, меткой le="L" и числом N в конце описывает счётчик. Счётчик говорит о том, что система зарегистрировала N значений с указанным набором меток, каждое из которых меньше или равно L. Эти значения L как раз задаются в клиентской библиотеке Prometheus при создании гистограммы.

Чтобы посчитать перцентиль в момент времени T за последние Y секунд, берутся попарные разницы между счётчиками гистограммы в моменты времени T и T-Y, а потом каждое значение в бакете делится на длину интервала агрегации. Далее из этих значений формируется набор бакетов с теми же значениями L. По этим данным будет считаться перцентиль. В нашем примере мы будем считать перцентили с момента старта пода примерно за 5 минут его работы. Деление значения счётчика в каждом бакете на одно и то же число не поменяет значение перцентиля, поэтому для упрощения расчётов мы пренебрежём этой корректировкой.

В нашем примере RT 9999 запросов не превышало 15 мс. В следующий бакет гистограммы попало 156 запросов, для которых RT не превышало 50 мс. 90% запросов, которые участвуют в вычислении 90-го перцентиля, — это 9139 запросов, и максимальный их бакет — (5; 15] мс. Это не противоречит ни графикам, ни ожиданиям, что ограничение в 20 мс работает. Но 99-й перцентиль RT покрывает уже 10 053 запроса. То есть Prometheus будет учитывать в том числе 54 наблюдения из бакета (15; 50] мс. Каким же образом Prometheus сможет посчитать перцентиль, если для расчёта ей придётся использовать только часть наблюдений из последнего бакета? Изучив исходный код, я выяснил, что для вычислений используется линейная интерполяция.

Линейная интерполяция

Линейная интерполяция — это способ вычислить значение функции между двумя известными точками. Допустим, у нас есть точки x1 и x2, для которых известны соответствующие значения f(x1) и f(x2). Необходимо вычислить значение в точке x, где x1<x<x2. Формула:

В нашем случае известными точками являются границы бакетов. Подставим наши значения — и получим 27 мс в 99-м перцентиле. Примерно столько мы и видим в среднем на графике в Grafana. Это больше нашего тайм-аута.

https://sopromat.xyz/ru/calculators/interpolation/linear

То есть гистограммы Prometheus дают только приблизительные значения перцентилей. Наверное, к этой мысли можно прийти в момент, когда вы понимаете протокол обмена данными между библиотекой и Prometheus. Но обычному разработчику понять этот нюанс просто из API библиотеки достаточно сложно. Ведь как оно бывает: завёл в коде гистограмму с какими-то бакетами, добавил график в Grafana — и Grafana что-то вам рисует, профит! С этого открытия и началось моё погружение в кроличью нору гистограмм Prometheus.

Главный инсайт

Первый вывод, который следует из алгоритма: для вычисления перцентилей не важны абсолютные значения наблюдений в последнем бакете — важна только доля наблюдений, которая будет взята для вычисления перцентиля, относительно общего числа наблюдений, попавших в бакет. Чем больше наблюдений нужно взять из последнего бакета, тем больше будет перцентиль. И совсем не важно, что реальное значение «честного» перцентиля могло быть едва выше нижней границы бакета. Исходные данные наблюдений утрачиваются ещё клиентом, который просто увеличивает значения счётчиков тех бакетов, в которые попало наблюдение. Разработчики Prometheus заявляют, что гистограмма с дефолтным распределением границ бакетов позволяет считать перцентили c максимальной относительной ошибкой в 42,9%. То есть чем больше абсолютные значения наблюдений, тем больше и ошибка. Если продолжить развивать эту идею, то можно прийти к ещё менее утешительным выводам.

Исследование эффектов от интерполяции при разных схемах бакетов

Напишем программу для проведения экспериментов, которая позволит эмулировать ситуации, когда некая ручка отвечала сначала быстро (назовём это множество значений времени ответов fast), а потом начала отвечать медленнее (назовём это slow). Посмотрим, что нам покажут графики разных перцентилей относительно точных расчётов.

Наша программа будет:

  1. Генерировать два набора случайных величин с заданными нормальными распределениями RT. На практике распределение будет другим, но мы будем использовать нормальное для наглядности, сути это не меняет.

  2. Строить визуализацию распределения для визуального контроля, что оно получается именно таким, какое нам требуется.

  3. Считать точные перцентили каждого множества RT, так как у неё будут исходные данные.

  4. Содержать веб-сервер, через который Prometheus будет забирать эти наблюдения в виде гистограммы, а Grafana — рисовать вычисленные Prometheus перцентили. У нас будет две гистограммы. Первую с широкой схемой бакетов назовём base: 1 мс, 5 мс, 15 мс, 50 мс (base buckets). Вторую с узкой схемой назовём precise: 1 мс, 5 мс, 10 мс, 20 мс, 30 мс, 40 мс, 50 мс (precise buckets).

Пример программы и необходимого окружения: https://github.com/OStrekalovsky/funs-with-histograms

Нечувствительность гистограмм к изменениям в пределах бакета

Эмулируем ситуацию, когда ручка отвечала 20 мс, а стала отвечать 40 мс. Изменение достаточно существенное, и мы ожидаем, что оно будет заметно на графиках.

Схема

stddev (мс)

mean (мс)

p50 (мс)

p90 (мс)

p99 (мс)

fast

1

20

20

21

22

slow

1

40

40

41

42

Графики по сырым данным

Графики после агрегации в Prometheus

Видим, что при base buckets разница в перцентилях отсутствует, а графики, построенные по precise buckets, разницу вполне уловили и показывают более приближенную к реальности картину.

Гиперчувствительность гистограмм на границе бакетов

Эмулируем ситуацию, когда ручка отвечала 13 мс, а стала отвечать 15 мс. Небольшое изменение — но что покажут графики?

Схема

stddev (мс)

mean (мс)

p50 (мс)

p90 (мс)

p99 (мс)

fast

1

13

13

14

15

slow

1

15

15

16

17

Графики по сырым данным

Графики после агрегации в Prometheus

Видим, что в случае с base buckets изменение медианы времени ответа на 2 мс дало увеличение p99 c 15 до 48 мс, хотя по факту оно увеличилось с 15 до 17 мс. А при precise buckets изменение едва можно заметить.

Комбинация нечувствительности и гиперчувствительности способна порождать ситуации, когда практически невозможно понять причину замедления сервиса. Представим, что при обработке запроса ваш сервис последовательно обращается к двум другим и вы измеряете RT каждого из них, а также итоговое RT вашего обработчика. И вот один из сервисов начал притормаживать таким образом, что его RT всё ещё остаётся в пределах прежнего бакета, и на графиках его увеличение можно вообще не увидеть из-за недостаточной чувствительности гистограмм. Но именно эти несколько миллисекунд могут вытолкнуть итоговое RT в больший бакет, и из-за гиперчувствительности графики вам покажут, что ваш сервис существенно замедлился. Имея только такие графики, сложно понять, в чём проблема. И чем больше внешних вызовов в обработчике, тем сложнее становится анализ. В общем, не так страшны сами ошибки, как их накопление.

100-й перцентиль — это…

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

Первый интервал:

Схема

stddev (мс)

mean (мс)

p100 (мс)

fast

1

20

23

slow

1

40

43

Второй интервал:

Схема

stddev (мс)

mean (мс)

p100 (мс)

fast

1

13

16

slow

1

15

18

Точные перцентили показывают:

  • для fast p100 сначала должен быть равен 23 мс, а потом — 16 мс;

  • для slow p100 сначала должен быть равен 43 мс, а потом — 18 мс.

Графики после агрегации в Prometheus

Как мы видим на графиках, вместо этого p100 в обоих случаях совпадает с границей максимального бакета в каждый момент времени. Даже «точная версия» бакетов не помогла определить изменившийся максимум, хоть и почувствовала изменение. Это полностью соответствует и алгоритму Prometheus: так как 100-й перцентиль — это все значения RT, то из последнего бакета будут использованы все 100% значений и по формуле интерполяции получено значение, равное значению функции в правой точке. А это и есть правая граница максимального бакета, в который попадали значения наблюдений.

Возвращаясь к кейсу с тайм-аутами

Стало понятно, что проблем с «залипанием» сервиса на уровне сетевого взаимодействия у нас не было: это подтвердили нулевые метрики запросов, закончившихся с тайм-аутом, и отсутствие ошибок в логах. Но нельзя утверждать, что не было проблем с end-to-end-отзывчивостью gRPC-вызова целиком: значения метрики RT давали нам очень приблизительное понимание 99-го перцентиля при успешных запросах. Что же покажут метрики, если внешний сервис всё-таки точно будет не успевать отвечать нам вовремя?

Эксперимент с реальными тайм-аутами

Мы нашли сервис Y, запросы к которому периодически завершались тайм-аутами: это было видно и по логам ошибок, и по графикам RT для запросов, закончившихся ошибками. При настроенном тайм-ауте запросов в 100 мс на этих графиках мы видели RT более 200 мс на высоких перцентилях для запросов, которые завершились тайм-аутами. Хотелось понять, точно ли рантайм не «залипает» настолько долго при тайм-аутах запросов.

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

  • выставляем тайм-аут обращения к внешнему сервису в 20 мс, что не укладывается даже в round-trip time;

  • пишем в файл реальное время выполнения запросов;

  • измеряем время максимально близко к месту gRPC вызова внешнего сервиса Y.

Содержимое файла

time=0.02044 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02028 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02057 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02035 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02025 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02021 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02030 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02037 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02118 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02020 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02114 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02063 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02103 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02083 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02043 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02025 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02082 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02022 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02034 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02060 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02110 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02034 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02088 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02055 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02084 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02067 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02057 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02053 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02099 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02112 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02161 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02105 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02089 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02049 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02040 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02127 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02084 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02066 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02037 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02098 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02100 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02119 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02113 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02055 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02108 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02095 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02118 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02055 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02077 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02025 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02122 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02105 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02129 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02075 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02073 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02035 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02053 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02099 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02092 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02034 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02128 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02045 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02044 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02041 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02049 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02074 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02044 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02027 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02052 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02104 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02032 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02068 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02074 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02067 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02074 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02105 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02033 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02029 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02059 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02121 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02126 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02023 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02112 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02042 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02038 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02040 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02082 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02083 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02090 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02098 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02029 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02027 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02068 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02038 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02045 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02033 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02020 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02069 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02077 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02161 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02096 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02072 rpc error: code = DeadlineExceeded desc = context deadline exceeded
time=0.02052 rpc error: code = DeadlineExceeded desc = context deadline exceeded

Если поискать вхождение паттерна time=0.021 в результатах замеров, то можно увидеть, что 23 запроса выполнялись на 1 мс дольше, чем величина тайм-аута. Ожиданий 22 мс и более нет.
Наши платформенные метрики RT дали следующие результаты:

ozon_external_service_response_time_seconds_bucket{external_service="Y",method="Ymethod",status="timeout",le="0.005"} 0
ozon_external_service_response_time_seconds_bucket{external_service="Y",method="Ymethod",status="timeout",le="0.015"} 0
ozon_external_service_response_time_seconds_bucket{external_service="Y",method="Ymethod",status="timeout",le="0.05"} 103
ozon_external_service_response_time_seconds_bucket{external_service="Y",method="Ymethod",status="timeout",le="0.1"} 103
ozon_external_service_response_time_seconds_bucket{external_service="Y",method="Ymethod",status="timeout",le="0.25"} 103
ozon_external_service_response_time_seconds_bucket{external_service="Y",method="Ymethod",status="timeout",le="0.5"} 103
ozon_external_service_response_time_seconds_bucket{external_service="Y",method="Ymethod",status="timeout",le="0.75"} 103
ozon_external_service_response_time_seconds_bucket{external_service="Y",method="Ymethod",status="timeout",le="1"} 103
ozon_external_service_response_time_seconds_bucket{external_service="Y",method="Ymethod",status="timeout",le="1.5"} 103
ozon_external_service_response_time_seconds_bucket{external_service="Y",method="Ymethod",status="timeout",le="2"} 103
ozon_external_service_response_time_seconds_bucket{external_service="Y",method="Ymethod",status="timeout",le="3.5"} 103
ozon_external_service_response_time_seconds_bucket{external_service="Y",method="Ymethod",status="timeout",le="5"} 103
ozon_external_service_response_time_seconds_bucket{external_service="Y",method="Ymethod",status="timeout",le="+Inf"} 103

Они показывают, что максимальное значение RT расположено где-то в интервале (15; 50] мс, и это не противоречит логам. Если построить высокие перцентили, то они покажут, что при тайм-ауте наш сервис ждал ответа почти 50 мс, что существенно больше реальных значений.

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

Заведём новую метрику ozon_cart_precise_y_service_duration_seconds с бакетами: 1 мс, 5 мс, 19 мс, 20 мс, 21 мс, 22 мс, 25 мс, 250 мс, 1 с и повторим эксперимент.

Логи и платформенные метрики показали схожие данные, а новая метрика — более контрастную картину:

ozon_cart_precise_y_service_duration_seconds_bucket{status="timeout",le="0.001"} 0
ozon_cart_precise_y_service_duration_seconds_bucket{status="timeout",le="0.005"} 0
ozon_cart_precise_y_service_duration_seconds_bucket{status="timeout",le="0.019"} 0
ozon_cart_precise_y_service_duration_seconds_bucket{status="timeout",le="0.02"} 0
ozon_cart_precise_y_service_duration_seconds_bucket{status="timeout",le="0.021"} 80
ozon_cart_precise_y_service_duration_seconds_bucket{status="timeout",le="0.022"} 103
ozon_cart_precise_y_service_duration_seconds_bucket{status="timeout",le="0.025"} 103
ozon_cart_precise_y_service_duration_seconds_bucket{status="timeout",le="0.25"} 103
ozon_cart_precise_y_service_duration_seconds_bucket{status="timeout",le="1"} 103
ozon_cart_precise_y_service_duration_seconds_bucket{status="timeout",le="+Inf"} 103
ozon_cart_precise_y_service_duration_seconds_sum{status="timeout"} 2.131312621
ozon_cart_precise_y_service_duration_seconds_count{status="timeout"} 103

С новой метрикой максимум RT находится где-то в интервале (21; 22] мс, что полностью совпадает с результатами абсолютно точных измерений.

Выводы из эксперимента:

  1. Подбор бакетов под SLA положительно сказывается на точности измерений.

  2. Превышение RT даже при тайм-аутах происходит в пределах 2 мс.

Гипотеза о причинах больших RT при тайм-аутах

При возвращении к первоначальному вопросу о странных графиках для запросов в сервис Y при тайм-аутах появилась гипотеза о том, что они вызваны слишком большим бакетом, куда попадают значения RT, а на самом деле превышения RT должны быть больше тайм-аута на единицы миллисекунд. Изучив бакеты платформенной гистограммы, я обнаружил, что есть бакеты (50; 100] и (100; 250], и это усилило мои подозрения. 

Встал вопрос: какие бакеты нужно подобрать, чтобы при тайм-ауте в 100 мс получить более адекватную картину? Вспоминаем, что в эксперименте с локальными запросами мы видели, что RT при тайм-ауте всегда больше тайм-аута. Это логично, так как таймеры не должны срабатывать раньше порога. Если таймер срабатывает абсолютно точно, то всё равно проходит какое-то время, прежде чем мы измерим RT запроса. Это значение не попадёт в бакет, у которого верхняя граница равна тайм-ауту, а попадёт, скорее всего, в следующий. Следовательно, и точность измерения перцентилей будет зависеть от ширины следующего бакета. То есть, если мы нарежем бакеты достаточно мелко чуть правее границы тайм-аута, то ожидаем увидеть более низкие значения перцентилей, чем нам дают платформенные метрики.

Эксперимент на проде

Отдельная гистограмма precise была задеплоена на обращения к сервису Y с бакетами: 1 мс, 5 мс, 99 мс, 100 мс, 101 мс, 102 мс, 105 мс, 250 мс, 1 с. Тайм-аут на запрос — 100 мс.

Спустя сутки я сравнил перцентили по гистограмме платформы с перцентилями по гистограмме precise.

p90. Метрики платформы фиксируют, что RT при тайм-аутах иногда достигает 235 мс, в то время как RT кастомной метрики при тайм-аутах достигает 102 мс. Широкие бакеты в кастомной гистограмме для небольших значений RT ожидаемо привели к тому, что перцентили успешных ответов для кастомной гистограммы больше, чем для платформенной.

p99. Метрики платформы показывают, что RT при тайм-аутах подбирается к 250 мс, а кастомная метрика периодически имеет спайки больше 100 мс (227 мс). При внешнем вызове сервис «залипал» больше, чем на 105 мс, но не больше, чем на 250 мс.

Бакета размером 105 мс не хватало в 0,1% случаев. На мой взгляд, это хороший результат для рантайма Go. Поставьте лайк, если хотите узнать, почему даже запаса в 5 мс иногда не хватало :)

Что в итоге

Неудачно подобранные бакеты в Prometheus плохо отражают реальность, поскольку могут быть как нечувствительны к существенным изменениям значений метрик, так и гиперчувствительны к несущественным. Поэтому слепо доверять абсолютным значениям перцентилей не стоит. Можно доверять изменению получаемых значений, но только если вы знаете, какие бакеты в гистограмме: если значение перцентиля на графике переместилось в другой бакет, реальное значение перцентиля точно изменилось.

Любые изменения перцентиля на графиках в пределах одного бакета — это спекуляции. Если в последний бакет, который использовался для вычисления перцентиля, стало попадать меньше значений метрики, то перцентиль в Prometheus уменьшится, но фактические значения метрик в этом бакете могли и вырасти, и точный перцентиль должен был при этом тоже увеличиться. Единственное, что можно утверждать, — что какой-то перцентиль точно уменьшился, так как какое-то множество наблюдений перестало попадать в последний бакет.

Вспоминаются нетленки от экспертов по бенчмаркингу:

  • Любые числа, которые дают вам инструменты мониторинга или бенчмаркинга, — это производные от реальных свойств системы. Важно стараться докапываться до первопричин, почему эти числа именно такие.

  • Выбранные инструменты могут не подходить для тех задач, с которыми вы столкнулись. Тот же Prometheus — это в первую очередь инструмент для мониторинга больших динамических сред, и компромиссы в его дизайне соответствующие. Ожидать от него точности уровня инструментов для бенчмаркинга не стоит.

  • Попытка делать выводы, опираясь на данные только из одного источника, работа которого ещё и не до конца вам понятна, — это прямой путь к измерению шума со всеми вытекающими последствиями. В экспериментах необходимо строить совместимую картину мира: перепроверять очевидные факты, собирать данные из разных источников и убеждаться, что они не противоречат друг другу.

P. S. Что делать с подсчётом перцентилей

Если вам достаточно просто понимать, когда, например, RT внезапно улетает в космос, то можно ничего не делать. Даже стандартные бакеты Prometheus помогут вам это определить. Но если вам нужно большее, то придётся поднапрячься.

Мы уже знаем, что чем меньше по размеру бакеты, тем точнее будут перцентили. Но создавать много бакетов — тоже плохо. Это увеличит объёмы хранения данных Prometheus. Разработчики Prometheus рекомендуют использовать в гистограммах не больше 20 бакетов. На практике этот лимит урезают ещё сильнее. Мне видятся следующие варианты решения проблемы.

Вариант №1

Подбирать бакеты так, чтобы они были максимально узкими в районе ожидаемых или желаемых значений. Это то, что рекомендуют разработчики Prometheus. То есть если у вас есть SLO на 90-й перцентиль, то и бакеты в районе этого значения должны быть более узкими. 

Однако этот подход плохо работает, если вы хотите измерять RT без привязки к SLO. Для получения высокой точности метрик бакетам придётся зависеть от фактического распределения собираемых данных, и границы бакетов, возможно, придётся периодически менять. Сложности на этом не заканчиваются: если вы измеряете RT вашего сервиса с точки зрения других внешних сервисов, то разные схемы бакетов в разных сервисах будут давать разные значения перцентилей. Также стоит учитывать описанный выше кейс с выбросами RT при тайм-аутах.

Вариант №2 

Если вам не нужна агрегация, то можно вместо гистограммы использовать тип метрики summary. Она считается на клиенте и точнее гистограммы, но получить агрегированное значение перцентиль в общем случае нельзя. Если вам агрегация всё-таки нужна, то набор из нескольких summary метрик можно использовать для ручной сверки с данными гистограмм.

Для создания summary придётся определить интересующие вас пары <квантиль: погрешность квантиля>. Например, задавая квантиль 0,95 и погрешность 0,01, мы говорим, что нас устраивает ответ в диапазоне квантилей от 0,94 до 0,96.

Возьмём наши примеры с распределениями fast и slow и сравним результаты summary с данными гистограммами и точными квантилями. Используем пары <0.5:0.0001>, <0.99:0.0001>, <1:0.0001>.

Схема

stddev (мс)

mean (мс)

p50 (мс)

p99 (мс)

p100 (мс)

fast

1

13

13

15

16

slow

1

15

15

18

18

Схема

stddev 

mean (мс)

p50 (мс)

p90 (мс)

p100 (мс)

fast

1

20

20

22

23

slow

1

40

40

42

43

Видим, что в обоих примерах результаты у summary точнее, чем у гистограмм.

Вариант №3 

Сменить технологию сбора и расчёта метрик. Если какой-то инструмент позволяет вам считать перцентили по сырым данным — это самое гибкое и точное решение.

Вариант №4

Перейти на native histograms в Prometheus. Изменения в Prometheus и библиотеках достаточно существенные, но, по заявлению авторов, достигается максимальная относительная ошибка 4,3% вместо 42,9%. Новый подход заключается в том, чтобы использовать больше бакетов, чтобы повысить точность расчета перцентилей, и одновременно сэкономить место в хранилище, не храня пустые бакеты. Новые гистограммы не передаются в старом текстовом формате в Prometheus, а используют protobuf. Из минусов — эта функциональность ещё экспериментальная. Но о ней уже не раз рассказывали на конференции PromCon.

Построим графики для наших примеров.

Схема

stddev (мс)

mean (мс)

p50 (мс)

p99 (мс)

p100 (мс)

fast

1

13

13

15

16

slow

1

15

15

18

18

Схема

stddev

mean

p50 (мс)

p90 (мс)

p100 (мс)

fast

1

20

20

22

23

slow

1

40

40

42

43

Видим, что native histograms точнее обычных гистограмм даже без какого-то тюнинга под ожидаемые значения метрик.

Подробности о новых гистограммах можно узнать в спецификации. Недавно и документация на сайте Prometheus о гистограммах в целом стала информативнее.

Посмотреть доклады об их разработке можно на канале PromCon:

О тестах потребления ресурсов: CNCF 2023 “Prometheus Native Histograms in Production - Björn Rabenstein, Grafana Labs”

Опыт первых пользователей: PromCon 2024 - Shopify's journey from conventional to native histograms

Вариант №5

Если ничего фундаментально вы изменить не можете, добавьте на графики информацию о границах бакетов, чтобы понимать, когда изменения на графиках находятся в границах погрешности инструмента, — и ссылку на эту статью 🙂