← назад к разделу

Есть класс проблем, который проходит мимо всей остальной наблюдаемости. Тесты зелёные, логи чистые, ошибок нет — а сервис через три дня после выката перезапускается сам. Или отвечает всё медленнее, хотя запросов столько же.

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

В Go на него отвечает pprof — профилировщик, встроенный в рантайм и стандартную библиотеку. Ничего ставить не нужно, и, в отличие от снимка кучи JVM, профиль кучи снимается с живого сервиса без остановки процесса. Про него и статья.

Обязательно

Как отличить утечку от нормальной работы

Прежде чем что-то снимать, полезно убедиться, что проблема вообще есть. Растущий график памяти сам по себе ни о чём не говорит: рантайм Go берёт память у операционной системы охотно и возвращает неспешно, так что «занято много» — обычное состояние здорового сервиса.

Смотреть надо на другое — на уровень, до которого память падает после сборки мусора. Здоровый сервис даёт пилу: go_memstats_heap_alloc_bytes растёт, приходит сборщик, память падает примерно к одному и тому же уровню, и так по кругу. Утечка выглядит как та же пила, у которой нижние зубцы медленно ползут вверх: после каждой уборки остаётся чуть больше, чем в прошлый раз. Та же картина у go_memstats_next_gc_bytes — цели следующей сборки: при GOGC=100 она равна удвоенному живому объёму, и если ползёт она, ползут живые данные.

У Go есть второй график, которого нет у других рантаймов, и смотреть на него надо первым: go_goroutines. Самая частая утечка в Go — не объекты, а горутины. Каждая держит стек от двух килобайт и всё, на что ссылается; тридцать тысяч горутин, застрявших на канале, — это и память, и забитый планировщик. Если go_goroutines растёт линейно со временем работы, дальше можно не гадать.

Посмотреть текущее состояние рантайма можно, ничего не устанавливая:

GODEBUG=gctrace=1 ./app

Каждая сборка печатает одну строку: gc 211 @3600.1s 2%: … 812->830->402 MB, 824 MB goal … — куча до сборки, в пике и после, цель следующей. Третье число и есть нижняя точка пилы; если оно растёт от строки к строке при ровной нагрузке, утечка есть. Разбор остальных полей строки — в разделе «Глубже».

Первый взгляд: кто занимает память

В сервисе должен быть открыт профилировщик — на служебном порту, не на бизнес-портах:

import _ "net/http/pprof"

mgmt := http.NewServeMux()
mgmt.Handle("/debug/pprof/", http.DefaultServeMux)
go http.ListenAndServe("127.0.0.1:6060", mgmt)

Импорт с подчёркиванием регистрирует обработчики на http.DefaultServeMux, и если бизнес-роутер тоже на нём, профили окажутся открыты наружу. Поэтому служебный сервер — отдельный, об этом статья про настройку наблюдаемости.

Дальше один запрос с ноутбука:

go tool pprof -top -sample_index=inuse_space http://orders:6060/debug/pprof/heap

Вывод — список функций, отсортированный по памяти, которую выделили они и которая жива сейчас:

      flat  flat%   sum%        cum   cum%
 1812.41MB 71.03% 71.03%  1812.41MB 71.03%  shop/internal/pricing.(*Cache).Get
  402.17MB 15.76% 86.79%   402.17MB 15.76%  bytes.growSlice
  118.03MB  4.63% 91.42%   118.03MB  4.63%  github.com/jackc/pgx/v5/pgproto3.(*chunkReader).Next

Читается это так: почти два гигабайта живой памяти выделены в Cache.Get — не «Go прожорливый», а конкретное место в коде, которое что-то держит.

Про цену. Профиль кучи не останавливает сервис: рантайм учитывает выделения выборочно, по умолчанию одно на каждые 512 КБ (runtime.MemProfileRate), и к моменту запроса статистика уже собрана. Запрос профиля вызывает сборку мусора, чтобы в выборке остались только живые объекты, — это миллисекунды, а не десятки секунд. Поэтому профиль кучи снимают с продового экземпляра без подготовки и выведения из-под нагрузки.

У профиля четыре разреза, и первый выбор решает, что вы увидите. inuse_space — сколько памяти живо сейчас и где выделено: разрез для утечек. alloc_space — сколько выделено за всё время работы, включая давно собранное: разрез для частых сборок мусора и нагрузки на процессор. inuse_objects и alloc_objects — то же в штуках, полезно, когда объектов миллионы, но каждый мал.

Снимок: как читать, чего в нём нет

Профиль сохраняют файлом и открывают в браузере:

curl -s -o heap.pprof http://orders:6060/debug/pprof/heap
go tool pprof -http=:8081 heap.pprof

Браузер показывает граф вызовов, диаграмму-«пламя» и исходный код с цифрами на строках. Смотреть стоит в таком порядке.

Top по flat — где выделено больше всего живой памяти. Это ответ на «что лежит».

Пламя или граф по cum — через какие вызовы туда пришли: Cache.Get вызывается из обработчика цены, а тот — из каждого запроса каталога. Это ответ на «откуда растёт».

Исходник (list Cache.Get) — конкретная строка: c.items[key] = price. Здесь обычно и становится видно, что ключ составлен из идентификатора покупателя.

Сравнение двух снимков. Самый надёжный приём для медленной утечки: снять профиль, подождать час, снять второй и показать разницу — go tool pprof -base heap1.pprof heap2.pprof. Всё, что выросло, видно сразу, а постоянная память сервиса не мешает.

И честное ограничение, которое надо знать до того, как поверить в «снимок всё покажет». Профиль кучи Go помнит, где объект был выделен, но не кто его сейчас держит. Цепочки ссылок от корня до объекта, как в Eclipse MAT, в pprof нет. На практике это редко мешает: место выделения плюс чтение кода почти всегда называет держателя, потому что в Go объект обычно держит тот, кто его создал, — срез, карта или горутина в той же функции. Когда этого не хватает, остаётся второй профиль — горутин.

Профиль горутин: самая частая утечка

go tool pprof -top http://orders:6060/debug/pprof/goroutine

Профиль группирует горутины по стеку: три строки с числом 9 812 напротив одного и того же места — и держатель найден. Полный текст каждого стека даёт /debug/pprof/goroutine?debug=2: там видно, на чём горутина стоит и сколько минут, например [chan send, 47 minutes].

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

func fetchAll(ctx context.Context, ids []string) []Item {
    out := make(chan Item)
    for _, id := range ids {
        go func() { out <- load(ctx, id) }()
    }
    var items []Item
    for range ids {
        select {
        case it := <-out:
            items = append(items, it)
        case <-ctx.Done():
            return items
        }
    }
    return items
}

Когда контекст отменяется на половине, функция возвращается, а оставшиеся горутины навсегда стоят на out <- …: канал небуферизованный, читать его больше некому. Лечится буфером размером с len(ids) или errgroup с контекстом, который горутины тоже слушают. Вторая классика — time.After внутри цикла select: каждый виток создаёт таймер, который живёт до срабатывания, и при частом цикле их миллионы; лечится одним time.NewTimer с Reset или time.Ticker со Stop. Третья — горутина, запущенная «на фоне» без контекста и без способа остановиться: сервис завершает запрос, а горутина ждёт ответа от соседа без таймаута.

Пять утечек, которые встречаются чаще остальных

Полезно знать типовые случаи: в девяти расследованиях из десяти находится один из них.

Кэш без ограничения. Обычная карта, в которую складывают результаты «чтобы быстрее». Пока ключей мало, всё хорошо; когда ключом становится идентификатор пользователя, карта растёт вечно.

type PriceCache struct {
    mu    sync.Mutex
    items map[string]Price
}

func (c *PriceCache) Get(sku string, customer Customer, calc func() Price) Price {
    key := sku + ":" + customer.ID
    c.mu.Lock()
    defer c.mu.Unlock()
    if p, ok := c.items[key]; ok {
        return p
    }
    p := calc()
    c.items[key] = p
    return p
}

Ревью этот код проходит легко: мьютекс на месте, вычисление по требованию. Утечка спрятана в ключе: sku — конечное множество, а customer.ID — нет. Лечится не «не кэшировать», а явным ограничением: ristretto или otter с пределом по размеру и сроком жизни, либо простая карта с TTL и уборкой по тикеру. Правило: любая коллекция, живущая дольше запроса, обязана иметь ограничение.

Срезы и подстроки, держащие большой массив. header := body[:64] сохраняет ссылку на весь буфер body, пока жив header; срез из гигабайтного ответа, положенный в карту, держит гигабайт. То же с bytes.Buffer, который переиспользуют после огромной записи: его внутренний массив не уменьшится. Лечится копированием: bytes.Clone, strings.Clone, append([]byte(nil), src...).

Горутины. Разобраны выше; это первое, что проверяют.

Незакрытые тела ответов и соединения. resp.Body, который не дочитали и не закрыли, не возвращает соединение в пул: открываются новые, у каждого две горутины транспорта и буферы, а на той стороне кончаются дескрипторы. defer resp.Body.Close() после проверки ошибки и io.Copy(io.Discard, resp.Body) перед закрытием, если тело не читали.

Таймеры, тикеры и подписки. time.NewTicker без Stop, подписка на события без отписки при пересоздании компонента, обработчик, добавленный в глобальный реестр на каждый запрос. Со временем в памяти живут десятки поколений одного и того же объекта.

Две утечки, которых не видно в профиле кучи

График heap_alloc ровный, профиль кучи чистый, а процесс всё равно растёт и в итоге погибает по лимиту контейнера. Значит, память утекает не в куче Go, и pprof heap её не покажет по определению.

Память за пределами кучи: cgo и стеки. Всё, что выделила библиотека на C через cgo (драйвер SQLite, обработка изображений, криптография), рантайм Go не видит и не считает: C.malloc без C.free растит процесс при спокойной куче. Видно это по разнице process_resident_memory_bytes и go_memstats_sys_bytes: первое растёт, второе нет. Второй источник — стеки горутин: go_memstats_stack_inuse_bytes отдельно от кучи, и при тридцати тысячах горутин это сотни мегабайт.

Память, которую рантайм ещё не вернул. Сборщик освободил объекты, но операционная система получит страницы обратно не сразу: фоновый возврат работает постепенно, и process_resident_memory_bytes держится выше живых данных минутами. Это не утечка, а задержка, и отличают их по графику: утечка растёт монотонно, задержка выходит на полку. Если полка выше лимита контейнера, помогает GOMEMLIMIT: при приближении к пределу рантайм собирает чаще и возвращает память агрессивнее.

Общее правило: если куча спокойна, а процесс растёт, сравнивают четыре числа — heap_inuse, stack_inuse, sys и resident — и разница между ними называет категорию до того, как снят хоть один профиль.

Профилирование процессора: где тратится время

Вторая половина темы — не память, а скорость. Метрика говорит, что обработчик стал медленнее, но не говорит, на чём именно.

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

go tool pprof -http=:8081 "http://orders:6060/debug/pprof/profile?seconds=30"

Тридцать секунд сервис работает как обычно, потом открывается браузер с диаграммой-«пламенем». Широкая полоса — функция, в которой проведено много времени. Четыре вещи, которые в ней ищут: самые широкие полосы в бизнес-коде; долю runtime.gcBgMarkWorker и runtime.mallocgc — если сборщик занимает четверть процессора, причина в выделениях, и дальше смотрят alloc_space; syscall и netpoll — время в ожидании ввода-вывода, которое не ускорить кодом; и runtime.futex с sync.(*Mutex).Lock — борьбу за блокировки.

Для блокировок есть свои профили, по умолчанию выключенные, потому что стоят дороже:

runtime.SetBlockProfileRate(1_000_000)
runtime.SetMutexProfileFraction(100)

/debug/pprof/block показывает, где горутины ждут каналов и мьютексов, /debug/pprof/mutex — кто эти мьютексы держит. Включают их на время расследования, не навсегда.

Когда нужно понять не «где», а «почему медленно именно сейчас» — паузы сборщика, задержки планировщика, горутина, которая не получает процессор, — снимают трассу рантайма: /debug/pprof/trace?seconds=5 и go tool trace trace.out. Это самый подробный и самый тяжёлый инструмент, пять секунд его обычно хватает.

И непрерывное профилирование: Pyroscope или Parca собирают профили со всех экземпляров постоянно и хранят историю. Тогда вопрос «почему вчера в три ночи было медленно» отвечается профилем за три ночи, а не повторением проблемы.

Как поймать утечку до продакшена

Всё выше — про расследование на живом сервисе. Половину таких историй можно закрыть раньше, и это стоит дешевле.

Тест на утечку горутин. go.uber.org/goleak проверяет, что после теста не осталось горутин, которых не было до него:

func TestFetchAll_NoGoroutineLeak(t *testing.T) {
    defer goleak.VerifyNone(t)

    ctx, cancel := context.WithTimeout(context.Background(), 10*time.Millisecond)
    defer cancel()

    _ = fetchAll(ctx, []string{"a", "b", "c", "d"})
}

Тест с примером из раздела про горутины падает: три горутины стоят на отправке в канал. Это ровно тот дефект, который потом стоит ночи, и ловится он за миллисекунды. goleak.VerifyTestMain(m) в TestMain проверяет весь пакет разом.

Тест на наблюдаемое свойство. Измерять память в тесте ненадёжно; проверяют размер коллекции, число открытых соединений, число подписчиков после тысячи операций с разными ключами:

for i := range 1000 {
    cache.Get("SKU-1", Customer{ID: fmt.Sprintf("customer-%d", i)}, calc)
}
if n := cache.Len(); n > 100 {
    t.Fatalf("cache grows per customer: %d", n)
}

Выделения в бенчмарке и под нагрузкой. go test -bench . -benchmem печатает allocs/op: обработчик с тремястами выделениями на запрос — это частые сборки и те самые паузы в хвосте задержки. Во время нагрузочного прогона снимают alloc_space: там обычно находится лишняя копия строки, fmt.Sprintf в горячем цикле или срез, растущий с нуля вместо make с ёмкостью.

Долгий прогон. Утечка по определению видна только со временем. Перед крупным выпуском гоняют умеренную нагрузку часами и смотрят два графика: нижнюю точку кучи после сборки и go_goroutines. Ползут за четыре часа — будут ползти и в проде.

Что поставить заранее. pprof на служебном порту на всех сервисах, графики go_goroutines, heap_inuse и next_gc на дашборде, GOMEMLIMIT в манифесте и -race в сборке. Ни одна из этих настроек не требует работы после установки, а вместе они превращают «сервис умер ночью» в «есть профиль за три ночи, разберём утром».

Порядок действий, когда «сервис ест память»

Чтобы не метаться, полезно держать в голове последовательность.

Сначала два графика: go_goroutines и нижняя точка кучи после сборки. Растут горутины — профиль горутин, он назовёт стек за минуту. Растёт куча при ровных горутинах — профиль кучи с разрезом inuse_space, лучше два с интервалом в час и -base. Куча ровная, а процесс растёт — сравнить heap_inuse, stack_inuse, sys и resident: это cgo, стеки или ещё не возвращённая память.

Когда виновник найден, проверьте его по списку типовых утечек: почти всегда это горутина на канале, кэш с идентификатором в ключе, срез от большого буфера или незакрытое тело ответа. И добавьте goleak в тест того пакета, где нашли, — чтобы в следующий раз утечку поймала сборка.

Дополнительно: при первом чтении можно пропустить

Глубже: gctrace, GOGC и два разных концарасширенное

Утечка — медленный рост. Есть вторая история про память, которая выглядит как периодические замедления при здоровом графике, и её читают по следу сборщика.

Строка gctrace. gc 211 @3600.1s 2%: 0.11+640+0.05 ms clock, 0.9+310/1200/0+0.4 ms cpu, 812->830->402 MB, 824 MB goal, 0 MB stacks, 0 MB globals, 8 P. Номер сборки и секунда с запуска; доля процессора на сборку с начала работы; три времени: остановка мира в начале, фоновая разметка, остановка в конце — настоящие паузы это первое и третье, и они в сотнях микросекунд; 310 в блоке cpu — помощь сборщику из рабочих горутин, когда выделяют быстрее, чем он успевает; куча до, в пике, после и цель. Смотрят на частоту строк (каждые полсекунды — куча мала для потока выделений или GOGC занижен), на долю помощи (большая — выделения слишком частые) и на третье число (нижняя точка, из начала статьи).

Регуляторы. GOGC=100 — следующая сборка, когда куча удвоится относительно живых данных; выше — реже сборки и больше памяти, ниже — наоборот. GOMEMLIMIT — мягкий потолок всей памяти рантайма: при приближении сборщик работает чаще, а не даёт процессу умереть. В контейнере ставят оба: GOGC под профиль нагрузки, GOMEMLIMIT на 80–90 % лимита.

Два разных конца. fatal error: runtime: out of memory в журнале означает, что операционная система отказала рантайму в памяти — это видно, и перед этим gctrace показывает отчаянно частые сборки. OOMKilled с кодом 137 означает, что весь процесс превысил лимит контейнера и убит ядром снаружи: в журнале ничего, профиля нет. Превысила не куча, а процесс целиком: куча плюс стеки, память cgo и ещё не возвращённые страницы, и всё это вне графика heap_inuse. Подробный расчёт лимитов — в статье про рантайм Go в контейнере.

Порядок разбора периодических замедлений: p99 рядом с частотой сборок из go_gc_duration_seconds_count; совпали — сборщик, дальше alloc_space и GOGC; не совпали — не память, дальше профиль процессора и трасса в момент замедления.

Коротко

  • Метрики показывают, что память растёт; кто её держит — отвечает pprof. Утечка видна не по высокому потреблению, а по тому, что нижняя точка кучи после сборки и go_goroutines ползут вверх.
  • Профиль кучи снимается с живого сервиса без остановки: выборочный учёт выделений, сборка на миллисекунды; inuse_space для утечек, alloc_space для частых сборок, -base для разницы двух снимков.
  • Профиль кучи помнит место выделения, а не держателя; цепочек до корня в нём нет, держателя находят по месту выделения и коду или по профилю горутин.
  • Самая частая утечка Go — горутины: отправка в канал без читателя после отмены контекста, time.After в цикле, фоновая горутина без контекста; /debug/pprof/goroutine группирует их по стеку.
  • Типовые утечки памяти: кэш с идентификатором в ключе, срез от большого буфера, незакрытое тело ответа, тикер без Stop; любая коллекция дольше запроса обязана иметь ограничение.
  • Куча спокойна, а процесс растёт: cgo, стеки горутин или ещё не возвращённая память; сравнивают heap_inuse, stack_inuse, sys и resident.
  • Процессор профилируют тридцатисекундной выборкой на проде; блокировки — профилями block и mutex на время расследования; «почему именно сейчас» — трассой рантайма; историю — непрерывным профилированием.
  • До прода ловят goleak в тестах, проверкой размера коллекции, -benchmem и alloc_space под нагрузкой, многочасовым прогоном с двумя графиками.
  • gctrace читают по частоте строк, доле помощи сборщику и нижней точке; GOGC и GOMEMLIMIT ставят вместе; fatal error: out of memory — отказ системы рантайму, OOMKilled — весь процесс сверх лимита без следа в журнале.

Что почитать дальше