Имеем сервис: .net core, асинхронное (async/await) REST API которое читает/пишет из БД или кэша (Redis), фоновый обработчик на Hangfire, крутится на ubuntu.
Нагрузка слабая: ~4-7 rpc днем, по ночам падает до 0.1-1 rpc.
Есть логи и базовые метрики (память, cpu, кол-во запросов, время ответа и т.п.).
Память держится в пределах 40-100 Мб, треды — в пределах 8-12 штук.
95% по времени ответа ~10-50 мс (меряется именно время работы хендлера, без чтения/записи запроса/ответа).
Но, когда нагрузка спадает, то 99% начинает давать пики в 400-1200мс.
Заметна четкая корреляция с rpc: при штатной нагрузке отвечаем быстро, нагрузка ушла вниз и потом (спустя время) вверх — появляется пик.
Это буквально единичные запросы, ~0.2% от общей массы.
По логам они ничем не отличаются от обычных: sql запросы и чтение/запись из кэша отрабатывают так же быстро, как у остальных.
Было предположение, что дело в тред.пуле.
Типа когда нагрузка уходит, шедулер начинает прибивать лишние треды.
Соответственно, когда после понижения идет рост rpc, шедулеру нужно время на раскачку.
Подкрутил настройку minWorkerThreads в пуле, пики просадки стали чуть ниже — 300-700мс, но совсем не исчезли.
Не то, чтобы это было критично, но все же хочется убрать и эти 0.2% тормозов, т.к. объективных причин для них не видно.
Вот как бы их отследить, чтобы понять, в чем дело?
Что-то типа perfcollect/dotnet-trace collect, но не для всего подряд, а только для медленных запросов.
Здравствуйте, RushDevion, Вы писали:
RD>Есть идеи?
Может GC?
Прикрутить может есть горлышко в коде? Тот же redis однопоточный. Или просто запись на диск.
RD>>Есть идеи? G>Может GC?
Не похоже. GC отрабатывает регулярно и при высокой нагрузке (чуть чаще) и при низкой (чуть реже). Если бы влиял он, то пики были бы и при высокой нагрузке.
Хотя... проверю. Время в GC я сейчас в метриках не трекаю.
G>Прикрутить может есть горлышко в коде? Тот же redis однопоточный. Или просто запись на диск.
Тоже нет. Запросы к редису 1-2ms, без аномалий.
А бутылочное горлышко в коде скорее при высокой нагрузке себя проявить должно было.
Здравствуйте, RushDevion, Вы писали:
RD>А бутылочное горлышко в коде скорее при высокой нагрузке себя проявить должно было.
Я неправильно прочитал исходное сообщение, не понял проблемы.
Также предлагаю мониторить диск на серваках, особенно время ответа и длина очереди.
Я видел как HDD (не SSD) засыпали и потом при запросе почти секунду просыпались.
Дополню вводную.
95%/99% следует читать как 95/99-й перцентиль по времени ответа.
У сервиса две ноды, это виртуалки на VM-ware поверх собственного железного сервера.
Виртуалка — это 4 CPU, 8Gb RAM, диск SSD, сеть 1Gb.
Кроме самого сервиса и стандартных nix-демонов и FileBeat больше ничего не крутится.
Загрузка в пике по CPU/RAM виртуалки — не более 30%/35%, соответственно.
G>Действительно может быть дело в тредпуле, у МС даже статья есть на этот счет https://learn.microsoft.com/en-us/dotnet/core/diagnostics/debug-threadpool-starvation, там и все необходимые тулы указаны.
Я как раз эти счетчики (ThreadPool Queue Length/Thread Count) и смотрел в моменте. Ничего необычного не увидел.
Там точно не thread starvation, т.к. тредов стабильно 7-12 штук.
Очередь пула тоже большую часть времени по нулям, максимум что в ней видел — 13 задач.
Наверное, придется это в графану завести и понаблюдать.
G>Также предлагаю мониторить диск на серваках, особенно время ответа и длина очереди. G>Я видел как HDD (не SSD) засыпали и потом при запросе почти секунду просыпались.
Это есть. Правда только на диски железного сервера, а не виртуалки. Там без аномалий.
DP>Использовать Flame Graph — https://learn.microsoft.com/en-us/visualstudio/profiling/flame-graph
Хм... я что-то не очень понимаю, как это может помочь?
Да, можно увидеть, что съедает CPU и как-то это съоптимизировать.
Только у меня латентность мигает не под нагрузкой, а наоборот, когда нагрузка спадает.
Да и в CPU я точно не упираюсь.
DP>В качестве догадки: может в эти моменты кэши инвалидируются или ошибочно идут запросы к базе в обход кэша?
Это было бы слишком просто. Нет, залипнуть может любой запрос: и POST и GET, и с кэшом и без кэша.
Здравствуйте, RushDevion, Вы писали:
RD>Есть идеи?
Покрываешь тормозящие пути метриками подетальнее, тем самым локализуешь проблему. Как минимум поймешь кто у тебя тормозит, твой код, сиквел, редис и т.п. Дальше по обстоятельствам.
НС>Покрываешь тормозящие пути метриками подетальнее, тем самым локализуешь проблему. Как минимум поймешь кто у тебя тормозит, твой код, сиквел, редис и т.п. Дальше по обстоятельствам.
Спасибо, конечно, за участие.
Но это довольно очевидный совет.
Метрики, как я уже сказал, есть.
В том то и дело, что ни сиквел, ни база, ни мой код сам по себе не тормозят.
В общем, если интересно, то обнаружилась четкая корреляция с количеством потоков в пуле.
Т.е. штатно под нагрузкой в нем ~8-12 потоков и тормозов нет.
Нагрузка упала — потоков стало 2-3.
Нагрузка восстановилась — число потоков потихоньку начинает расти.
И вот в этот момент отдельные запросы могут вываливаться за 99%.
Потоки восстановились до 8-12 и снова все ОК, работаем без тормозов.
По итогу перевел имплементацию редис-локов с sync варианта на async и просадки практически пропали.
На этом пока остановился.
Здравствуйте, RushDevion, Вы писали:
НС>>Покрываешь тормозящие пути метриками подетальнее, тем самым локализуешь проблему. Как минимум поймешь кто у тебя тормозит, твой код, сиквел, редис и т.п. Дальше по обстоятельствам.
RD>Спасибо, конечно, за участие. RD>Но это довольно очевидный совет. RD>Метрики, как я уже сказал, есть.
Не те метрики. Тебе нужно самому их генерировать в нужных точках кода. По готовым метрикам сложно будет понять. Если не хочешь сам инструментировать — тогда включи трейсинг штатными средствами, из той же open telemetry, к примеру. Но это несколько более геморойная история, метрики проще.
RD>В том то и дело, что ни сиквел, ни база, ни мой код сам по себе не тормозят.
Вот тебе и надо выяснить, что именно тормозит, протыкав метриками все ключевые точки пути исполнения. Тогда ты увидишь полную картину.
НС>Не те метрики. Тебе нужно самому их генерировать в нужных точках кода.
Что здесь имеется ввиду? Можно пример кода, как это должно выглядеть?
Сейчас для сбора метрик используется Prometeus.NET, визуализируется в Grafana.
Технически это как раз и сделано через "генерацию в нужных точках кода".
// Типа такого:
RedisCacheRequestsHistogram.Observe(requestTimeMs);
RedisCacheRequestCounts.WithLabels("users").Inc();
ApiRequestCounter.WithLabels("GET", "200", "/users").Inc();
И да, это именно метрики, т.е. некая общая картинка, без углубления в конкретный запрос.
Для конкретного запроса дополнительно пишутся логи, где тоже все тайминги есть.
> Если не хочешь сам инструментировать — тогда включи трейсинг штатными средствами, из той же open telemetry, к примеру. Но это несколько более геморойная история, метрики проще.
Имеется ввиду именно трейсинг, который в Jager/Zipkin/etc можно посмотреть?
Да, наверное, это более наглядная картинка в разрезе конкретного запроса.
Но вот представим, затянул я проект open telemetry, экспортнул трейсы через OTLС в тот же Jagger.
Нашел там томозящий запрос и вижу, что вся цепочка Contoller.cs <=> MyService.cs <=> Redis <=> БД отработала в пределах 100мс.
А на выходе из API (в логах NGINX) этот запрос занял 500 мс.
Ну как-то не очень помогло, да?
Здравствуйте, RushDevion, Вы писали:
RD>Что здесь имеется ввиду? Можно пример кода, как это должно выглядеть?
Тебе нужно в ключевых точках на пути исполнения вставлять запись значений в счетчики, время от начала. А потом на дашбордах будет видно какой кусочек тормозит.
RD>
RD>// Типа такого:
RD>RedisCacheRequestsHistogram.Observe(requestTimeMs);
RD>RedisCacheRequestCounts.WithLabels("users").Inc();
RD>ApiRequestCounter.WithLabels("GET", "200", "/users").Inc();
RD>
Здесь я вижу только одну запись счетчика на весь запрос, это ничего не покажет. Нужно что то вроде:
RD>И да, это именно метрики, т.е. некая общая картинка, без углубления в конкретный запрос.
Да, все верно. Для отдельных запросов тебе нужен трейсинг. Но прелесть метрик в том, что они дают статистику, и как раз на этой статистике можно легко отслеживать случайно-закономерные тормоза.
>> Если не хочешь сам инструментировать — тогда включи трейсинг штатными средствами, из той же open telemetry, к примеру. Но это несколько более геморойная история, метрики проще. RD>Имеется ввиду именно трейсинг, который в Jager/Zipkin/etc можно посмотреть?
Да.
RD>Нашел там томозящий запрос и вижу, что вся цепочка Contoller.cs <=> MyService.cs <=> Redis <=> БД отработала в пределах 100мс.
А ты это видишь реально или теоретизируешь? И да, цепочку можно начать не от контроллера, а от мидлвари, а можно и вообще от nginx.
Ок. Идея понятная, спасибо.
Но такой паттерн записи как-то не очень ложится на стандартные типы метрик.
Это не counter, не gauge, не histogram/summary.
Поэтому затрудняюсь представить, как это должно выглядеть на графиках.
НС>А ты это видишь реально или теоретизируешь? И да, цепочку можно начать не от контроллера, а от мидлвари, а можно и вообще от nginx.
Да, примерно так оно и выглядит.
Я это понимаю так, что внутрянка kestrel/asp net.core тоже использует потоки тредпула. И в какой-то момент возникает ситуация, когда потоков на всех не хватило, а тредпул еще не успел создать новые. В итоге мой код отработал быстро, а где нибудь ниже при асинхронной записи в сокет, оно подвисло, ожидая свободный поток.
Думаю, тут могла бы помочь настройка, которая сказала бы пулу, держать не менее N потоков. Но ничего похожего я не нашел.
Здравствуйте, RushDevion, Вы писали:
RD>Ок. Идея понятная, спасибо. RD>Но такой паттерн записи как-то не очень ложится на стандартные типы метрик. RD>Это не counter, не gauge, не histogram/summary. RD>Поэтому затрудняюсь представить, как это должно выглядеть на графиках.
Потому что это должны быть не метрики мониторинга, а спаны трейсинга. На "графике" выглядит как дерево запросов.
Но да, код придется доделывать для использование трейсинга
Здравствуйте, RushDevion, Вы писали:
RD>95% по времени ответа ~10-50 мс (меряется именно время работы хендлера, без чтения/записи запроса/ответа). RD>Но, когда нагрузка спадает, то 99% начинает давать пики в 400-1200мс. RD>Есть идеи?
Надо взять логи и сравнить типовой вызов за 50 мс и 500 мс. Разница покажет, где проблема.
Если есть трейсинг, то соответственно сравнить спаны
P.S. У тебя указаны разные персентили — 10-50 мс в 95% и 400-1200 мс в 99% — в общем случае их сравнивать невалидно же
пруфов найдете море, можешь выбрать подходящее по уровню токсичности. — главное нарекание кодо генрация для стейт машин медленно работает, по сути созйдавая оверхед для каких то сценариев.
Мой тейк таков — дело не в том быстрее это или медленнее, не использовать то на что потрачены человеко-стоелетия по сути сцать против ветра. Хотя, посмотрим, есть и обратный тренд, например, asp.net minimal api.
Здравствуйте, 尿컙拋㕪⬎⤇Ǥ꧃푙刾ꄔ, Вы писали:
尿Ǥ푙>пруфов найдете море, можешь выбрать подходящее по уровню токсичности. — главное нарекание кодо генрация для стейт машин медленно работает, по сути созйдавая оверхед для каких то сценариев.
Оверхед конечно есть. Но для IO-bound сервисов, коих большинство, этот крошечный оверхед абсолютно не заметен на фоне ускорения, которое может дать async/await (на порядки).
по большому счету it's not worth my while но, согласись, тот довод, что преимущества async/await снижаются (если не исчезают) по мере уменьшения доли простоев (aka idle) в общем времени логичен? и что есть высоконагруженная система как не система с минимальной долей idle?
