Несколько месяцев назад наш канал мониторинга в Slack был завален предупреждающими сообщениями о перезапуске микросервиса с необычно высокой частотой. При ближайшем рассмотрении оказалось, что рассматриваемая микрослужба перезапускалась из-за нехватки памяти. График использования памяти выглядел примерно так. Каждое падение на дно - это перезапуск 😬
Диагноз 🕵
Это было интересно, потому что мы не видели значительного всплеска нашего трафика, и мы действительно не вносили никаких серьезных изменений в этот конкретный микросервис какое-то время. Но явно что-то было не так. Итак, мы начали наше расследование 🔍 Вскоре мы поняли, что проблема возникла только после объединения определенного PR. Это было прекрасно, потому что помогло сузить сферу нашего исследования, и теперь мы могли сосредоточиться на изменениях, внесенных в этот PR. Поэтому мы начали смотреть, какие изменения были внесены в интересующий PR. К счастью для нас, это был небольшой PR, и это было изменение, чтобы сделать вызов одной из наших вспомогательных функций, которая выглядела примерно так:
Глядя на него, ничего особо не выделялось. Конечно, мы думали, что проблема не может быть в RunAsync
. Эта вспомогательная функция не была новым кодом, и она уже некоторое время находится в производстве.
Продолжая наше путешествие по отладке, мы добавили конечные точки pprof в наш микросервис, чтобы лучше понять, что происходит. Если вы не знакомы с тем, что такое pprof, советую прочитать эту статью. Он должен предоставить вам достаточно информации и ссылок на другие полезные ресурсы для начала работы. Короче говоря, pprof сэмплирует ваше приложение и предоставляет вам различные данные профилирования, которые дают вам больше информации о состоянии вашего приложения.
После того, как мы добавили pprof в микросервис и развернули его, мы загрузили профиль кучи из нашего микросервиса.
curl <baseUrl>/debug/pprof/heap --output heap1.out
Открытие файла,
// opens in the browser go tool pprof -http=":9090" heap1.out
наше внимание привлекла часть вывода, которая выглядела примерно так
Что бросалось в глаза, так это большой красный прямоугольник слева. Сначала мы не знали, что это такое, но после некоторого поиска в Google и просмотра исходного кода мы узнали, что runtime.malg
— это вызов для выделения стека только что созданной горутине. И горутина удерживает это до тех пор, пока не завершит выполнение.
Видя, что профиль кучи показывает относительно высокое использование памяти этой функцией, это может означать 2 вещи:
- утечка памяти в самой функции
- высокочастотный вызов функции
Мы быстро исключили 1
, так как вероятность наличия ошибки в runtime.malg
казалась очень низкой. С другой стороны, 2
имело для нас смысл, потому что мы вызывали RunAsync
(который запускал горутину) на одной из наших наиболее загруженных конечных точек, и это также было частью изменения, внесенного в наш проблематичный PR.
Почувствовав себя немного увереннее 🤠, мы еще раз внимательно рассмотрели реализацию RunAsync
, но пришли к тому же выводу: ничего подозрительного 😑. Что-то должно было быть не так 🤔 Наш метрический отчет в DataDog не врал 😕 Потом мы посмотрели, как вызывался RunAsync
, и тут до нас дошло 💡 Выяснилось, что вызывающий RunAsync
игнорировал возвращаемое значение RunAsync
🤦♂
func handler(w http.ResponseWriter, r *http.Request) { // set up for background processing RunAsync() // 👈 problem point // complete the request without waiting for the task to finish w.WriteHeader(http.StatusOK) }
Канал работает следующим образом:когда данные отправляются в небуферизованный канал, он блокируется до тех пор, пока данные не будут использованы другой горутиной.В нашем случае, потому что ничего не происходит. был использован вне канала, возвращенного RunAsync
, код был заблокирован в строке 5 в RunAsync
. Таким образом, пока doSomething()
выполнялась, она застряла в следующей инструкции, которая должна отправить возвращаемое значение doSomething()
в канал ch
. Это привело к ситуации с утечкой горутины, когда ни одна из горутин не завершила выполнение, поскольку каждая из них была заблокирована в ожидании, пока другая горутина не использует канал ch
. А это означало, что ресурсы, выделенные для каждой горутины, никогда не освобождались. Так что со временем он исчерпал всю доступную память в микросервисе и, в конце концов, разбил его.
Решение 👷
Мы рассмотрели два варианта исправления:
Опция 1:
func handler(w http.ResponseWriter, r *http.Request) { // set up for background processing go func() { ch := RunAsync() if err := <- ch; err != nil { log.Print(err) } }() // complete the request without waiting for the task to finish w.WriteHeader(http.StatusOK) }
Вариант 2:
func handler(w http.ResponseWriter, r *http.Request) { // set up for background processing go func() { if err := doSomething(); err != nil { log.Print(err) } }() // complete the request without waiting for the task to finish w.WriteHeader(http.StatusOK) }
В то время как оба решают проблему утечки горутины, вариант 1 запускает 2 горутины (потому что RunAsync
itself запускает 1 горутину), а вариант 2 запускает только 1 горутину. Увидев, что использование RunAsync
для того, чего мы пытались достичь, не дает дополнительных преимуществ, мы выбрали вариант 2. И о чудо, после того как мы развернули исправление (отмечено красной стрелкой ниже), график использования памяти нормализовался, и наш служба перестала перезапускаться 🎊
Это было для нас большим уроком. И я очень доволен тем, как мы смогли систематически сосредоточиться на проблеме 🙌 . Надеюсь, кто-то где-то найдет это обучение полезным и может быть сэкономит им несколько волнующих моментов 😉 До следующего раза, ура и никогда не прекращайте учиться! Также берегите себя 😷