Ничего не предвещало беды. Сижу, работаю, обычный день.
Прилетает алерт: CPU на редисе.
Открываю графики - ну офигеть, действительно много.
CPUUtilization уже почти в потолке. Смотрю на историю подольше, не за последний час, а за пару недель - а она там не спонтанно скакнула, она туда шла целенаправленно, полз-полз-полз последние недели вверх, и вот сегодня наконец доехала до трешхолда, который у нас на алерт стоит. Красивая, спокойная, методичная деградация. Как будто специально ждала, чтобы я это заметил именно во вторник.Стою на развилке, как обычно в таких случаях.
Вариантов, по сути, три сходу:
- поднять инстанс тип побольше - и вопрос закрыт. Минут на пятнадцать работы.
- копать почему нагрузка растёт - раз уж она растёт неделями, значит где-то есть тренд (мемори лик?), и если его не найти, он вернётся через месяц уже на инстансе побольше.
- полезть в релизы/код - может, кто-то тихо принёс что-то, что жрёт редис сильнее, чем раньше.
Времени в этот день было, под рукой прямых пожаров нет, так что решил нырнуть.
Начал копать. Смотрю на количество соединений к редису - и это тоже растёт. Причём растёт не гладко, а скачками.
Спустя время понял, что ровно в моменты редеплоев и скейлинга подов.
У меня в голове сразу щёлкает классика жанра: коннекшн лик.
Кто-то не закрывает соединения при рестарте пода, они копятся, some magic, редис в итоге не столько данные обрабатывает, сколько бегает между тысячами открытых, но по факту мёртвых клиентов.
Полез руками смотреть список клиентов - и что вы думаете, реально нахожу один клиент, зависший в цикле на одной и той же команде. Судя по времени коннекта - висит там натурально сутки, сука, с прошлого деплоя.
Убиваю его руками, CPU чуть проседает. Ага, думаю, вот он, зверь, поймал.
Порадовался я недолго. Потому что счётчик коннектов и без этого одного зомби-клиента всё равно был в районе четырёх тысяч, а нагрузка не сильно шевельнулась.
Сели разбираться вдвоём. У коллеги гипотеза жёстче моей: раз коннекты копятся, давай просто грубо перезапустим весь неймспейс с воркерами.
Убили все поды.
И - та-дам - нагрузка реально упала. Вот же оно, подумали мы, воркеры плодят коннекты при каждом релизе и не убирают их за собой, поэтому со временем только расти и расти.
Только вот через пару минут после того, как поды снова поднялись до штатного количества, коннекты вернулись ровно туда же, откуда были - к тем же четырём тысячам. Ни больше, ни меньше. Что как-то не очень бьётся с теорией "утечки": утечка накапливается со временем, а тут число просто вернулось на место и стабилизировалось.
Стали считать руками, вместо того чтобы верить на глаз. Взяли количество воркер-процессов на под, умножили на количество подов - и цифра сошлась с реальным числом коннектов почти впритык (разница пара процентов, спишем на процессы в момент рестарта). То есть на каждый воркер-процесс - одно соединение к редису на каждую используемую БД внутри инстанса. Это не утечка. Это ебаная архитектура. Просто у нас этих воркер-процессов оказалось значительно больше, чем реально нужно под текущую нагрузку - часть очередей держала по 20+ воркеров при спросе, близком к нулю.🤡
Осадочек неприятный: убийство подов "помогло" не потому что мы нашли причину, а потому что случайно совпало по времени с тем, что коннекты после ресета временно проседают, пока воркеры не долетят обратно до штатного числа. Классическая ловушка - совпадение по времени легко спутать с причинно-следственной связью, если не проверить цифры отдельно.
Ладно, коннекты - не утечка, они просто ожидаемо большие. Но CPU-то всё равно в потолке, и с этим ничего не сделало ни убийство подов, ни чистка зомби-клиента. Значит дело не в количестве соединений как таком, а в чём-то, что происходит с этими соединениями под нагрузкой.
Дальше - самая интересная часть. У ElastiCache есть слой "enhanced I/O" с io-threads, которые молотят входящий трафик отдельно от главного event-loop потока. И вот при определённом уровне конкурентных подключений без пайплайнинга этот флаг io_threads_active залипает в 1 - и тогда добрая половина основного (единственного, сука) engine потока улетает во busy-wait: не делает полезной работы, не в syscall, просто крутится в холостую, ожидая координации с io-потоками. Причём сама выполняемая команда - это 9-12% занятости потока, всё остальное - вот этот самый спин.
Проверили это экспериментально на реплике без прод-трафика: подняли конкурентные подключения без пайплайнинга - флаг щёлкнул с 0 на 1, и разрыв между "занят" и "реально делает команды" улетел с полутора процентов до пятидесяти. В 34 раза. Сняли нагрузку - всё вернулось на исходную позицию. Воспроизводится по требованию.
Самое обидное: нодовая метрика
CPUUtilization в CloudWatch при этом показывала спокойные 44% - потому что она про весь инстанс с его 8 vCPU, а не про то, что творится именно в главном движковом потоке. EngineCPUUtilization - вот метрика, которая реально видит проблему, а на неё у нас не было алерта вообще. Ни одного. Полезная информация лежала в CloudWatch всё это время, просто мы на неё не смотрели.🤡Дальше прогнали чек-лист на исключение всего остального, чем это могло быть: экспайры ключей - доли процента от жизни, evicted_keys - ноль, дефраг - ноль, решардинг хештейбла - ноль, keyspace-нотификации - учтены внутри команд и не создают отдельной нагрузки, скрипты/функции - вообще не используются, ни одной команды дольше 10мс за всё окно наблюдения. Это точно не медленный запрос и не утечка памяти. Это именно координационный оверхед в закрытом слое ElastiCache, который мы не видим и не можем настроить - параметр io-threads не выставлен наружу ни в одной из параметр-групп valkey, CONFIG SET для него заблокирован.
Раз рычага внутрь закрытого слоя AWS у нас нет - работаем с тем, что реально в наших руках:
- срезали количество воркер-процессов там, где спрос был почти нулевой, а супервизоров держали как для продакшна с полной загрузкой (одна из групп очередей - 22 воркера при спросе меньше десятка операций в сутки). Это прямо снижает число одновременных подключений, соответственно снижает шанс залипания флага в 1.
- добавили алёрт по
EngineCPUUtilization, а не только по CPUUtilization - потому что нодовая метрика в принципе не видит этот тип насыщения.- хардним ElastiCache client reaping и client-output-buffer-limit - отдельная гигиена, чтобы зомби-клиенты (тот самый, что я руками убил в начале) не жили сутками незамеченными.
- поправили
notify-keyspace-events - было включено с флагами, генерирующими события, которые вообще никто не читает (180 тысяч событий в секунду в пустоту, лол). Не фикс основной проблемы, но лишняя работа редиса, от которой легко избавиться.Первый подозреваемый почти никогда не виновник. Коннекты росли - я сразу подумал "лик". Убийство подов "помогло" - я почти поверил, что нашёл причину. А по факту оба раза я гонялся за симптомом, который просто совпал по времени с настоящим виновником, спрятанным на уровень ниже, там, куда обычная нодовая метрика вообще не смотрит.
Ссылки могут быть сейчас устаревшими, были актуальны на момент проблемы
- https://repost.aws/knowledge-center/elasticache-redis-high-cpu-usage
- https://medium.com/better-programming/redis-internals-client-sends-a-command-and-receives-a-response-9e3e8c463f7