Несколько месяцев назад наш канал мониторинга в 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. утечка памяти в самой функции
  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. И о чудо, после того как мы развернули исправление (отмечено красной стрелкой ниже), график использования памяти нормализовался, и наш служба перестала перезапускаться 🎊

Это было для нас большим уроком. И я очень доволен тем, как мы смогли систематически сосредоточиться на проблеме 🙌 . Надеюсь, кто-то где-то найдет это обучение полезным и может быть сэкономит им несколько волнующих моментов 😉 До следующего раза, ура и никогда не прекращайте учиться! Также берегите себя 😷