pprof в golang: Исправляем утечку памяти

За редкими исключениями (раз, два << оригинал отформатирован хуже, IMO) статьи про "профилирование" в golang представляют собой перепечатку аннотации к пакету pprof (даже не этой старой статьи) и дальше немного личного опыта про то как (не) удалось с помощью pprof найти проблему.

В общем, ощущается пробел в материалах "среднего" уровня. Когда есть более-менее разумный/рабочий код, он проходит тесты на соответствие модели, имеет документированные ТТХ и вообще всё (почти) хорошо. Потому что всего этого можно добиться и "по старинке", вообще только отладочными сообщениями и соответствующими тестами.

Но вот незадача: собранное "изделие" явно где-то "подтекает". (Не как на КДПВ, но всё же.) Потому что (в моём случае) сервис "без состояния", не набирающий кэшей (прямо таки "идеальный передаст") ну ни как не должен за месяц эксплуатации раздуваться на 20+МБ.

Забегая вперёд, для профилирования достаточно периодически куда-нибудь писа́ть "pprof.WriteHeapProfile()". Но есть нюанс: "из коробки" в профиль попадут только аллокации "жирнее" 512кБ. Мне осознание этого факта стоило почти целого рабочего дня (классическое "ЧЯНТД").

Вроде как есть вариант "писа́ть всё": вызывать "WriteTo()" для "кучи" с аргументом "debug=2":

pprof.Lookup("heap").WriteTo(some_file, 2)

Я успел закончить отладку раньше чем разобрался во всех нюансах pprof, так что эксперименты оставляю читателям статьи. Сейчас не найду, но там было примечание что так не делают "из коробки" потому что медленно.

• Разумеется, ничто не мешает подключить "net/http/pprof" и таскать профили через curl/wget. Хотя, в моём случае опять таки обнаружился нюанс: просто воткнув "http.ListenAndServe()" в конце инициализации, получаем не завершаемый по сигналам процесс. Т.к. сам "ListenAndServe()" сигналов не ловит. Не стесняйтесь воткнуть "go …" для выпуска интерфейса внутри goroutine.

Не буду копипастить методики применения pprof (и так весь поиск ими забит). Показываю конкретно то что понадобилось для решения задачи.

1. Подключаем дампы HeapProfile

import (
	"runtime"
	"runtime/pprof"
)
…
// Debug: pprof.WriteHeapProfile()
				memprofile := "/run/dnsd/memprofile"
				f, _ := os.Create(memprofile)
				runtime.GC() // get up-to-date statistics
				pprof.WriteHeapProfile(f)
				f.Close()
…
// Debug: pprof http listener
//	go http.ListenAndServe("localhost:8080", nil)

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

2. Что конкретно ищем

В моём случае память текла крайне медленно (первые 512 кБ набирались за 4…6 часов), поэтому 99% что ищем продолбанные ссылки.

В показанном ниже выводе безымянная goroutine "main.apiCall.func1()" успела натаскать себе более 10923 "объектов". (Более, т.к. в профиль попали два "забитых" по 512 кБ блока. А что-то ведь почти наверняка осталось в недозаполненном третьем…)

# go tool pprof -nodefraction=0 -inuse_objects memprofile.3+
File: dnsd
Type: inuse_objects
Time: Dec 24, 2020 at 10:38am (MSK)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 19387, 100% of 19387 total
Showing top 10 nodes out of 32
      flat  flat%   sum%        cum   cum%
     10923 56.34% 56.34%      10923 56.34%  main.apiCall.func1
      8192 42.26% 98.60%       8192 42.26%  regexp.mergeRuneSets.func2
       256  1.32% 99.92%        256  1.32%  bufio.NewWriterSize
        16 0.083%   100%         16 0.083%  compress/flate.(*dictDecoder).init

3. Вот здесь ошибка/ошибки

Примерно так это выглядело в момент начала отладки:

	// To complete report processing even after return on timeout
	go func () {
		defer report.DelNotifier(commands.UUID)

		signals := make(chan os.Signal, 1)
		signal.Notify(signals, syscall.SIGHUP, syscall.SIGINT, syscall.SIGKILL, syscall.SIGTERM)
		for {
			select {
			case index := <-callback:
				if (index + 1) >= len(Workers) {
					done <- struct{}{}
					return
				}
			case t:= <- timer: // t++ on each tick, t=-1 at the end
				if t > 0 {
					xl.Warn("apiCall: Timer tick while still not enough reports from workers!")
				}
				if t < 0 { // Time is over
					xl.Err("apiCall: Time over while still not enough reports from workers!")
					err = fmt.Errorf("Time over")
					done <- struct{}{}
					return
				}
			case exitSignal = <-signals:
				xl.Warnf("apiCall: Interrupt is detected: %s", exitSignal)
				xl.Warn("apiCall: Waiting for timeout to complete report processing...")
				err = fmt.Errorf("Interrupt")
				done <- struct{}{}
				return
			}
		}
	} ()

4. Что не так

Как видим, первое "мутное" место ссылается на "commands.UUID" за пределами асинхронной функции (commands объявлен в "родительской" функции). Вроде бы так можно, т.к. в этот момент переменная не "зачищена" и должна быть скопирована в defer. Но всё равно, лучше не лениться и явно протащить копию. Чтобы когда-нибудь потом не подпрыгивать. Как-то так:

go func (uuid string) {
…
} (commands.UUID)

Зачем я пытался перехватывать SIGKILL ("девятку"), я вам таки не скажу. Видимо, в момент копи-пасты думал о чём-то другом.

Наконец, переходим к "сладкому". А течёт-то где? А вот:

		signal.Notify(signals, syscall.SIGHUP, syscall.SIGINT, syscall.SIGKILL, syscall.SIGTERM)

То есть, для своего модуля я "defer report.DelNotifier()" написать не забыл. А что при выходе из функции никто за меня подписку на "signal.Notify()" не разберёт, в голову не пришло. Потому что в интернетах все кому не лень этот паттерн копипастят, а авторы "os.Signal" "как надо" проиллюстрировать постеснялись. Совсем. Чтобы, видимо, не отлынивали от чтения документации "от корки до корки".

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

5. Happy end

Добавляем в код:

defer signal.Stop(signals)

Тестируем, через сутки видим:

# go tool pprof -nodefraction=0 -inuse_objects memprofile.1
File: dnsd
Type: inuse_objects
Time: Dec 25, 2020 at 11:56am (MSK)
No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 0, 0% of 0 total
      flat  flat%   sum%        cum   cum%

Никто за без малого сутки ничего (заметного) не нацеплял. И это прекрасно. Потому что "транслирующий прокси" так и был задуман.

Заключение

Описывать однопоточные сценарии практически ни на одном ЯП сложностей не представляет.

Ходят слухи, что "функциональные" ЯП избавляют и от многих проблем многопоточного программирования (за счёт построения кода "наоборот"). Но я их (почти) не использую, т.к. сам "прикладник" (и черновик решения привык достраивать в "прямом" порядке).

В golang, несмотря на весьма удачную реализацию многопоточного процедурного программирования, есть ряд возможностей "нацеплять проблем". Из моей (не самой большой) практики:

• Отсутствие статического анализатора. Раз уж ошибки асинхронного использования объектов (хотя бы "первого порядка") поддаются анализу "глазами", можно и инструмент сделать. Но — нету до сих пор…

• Запись в "занулённый" канал из ранее запущенной goroutine (завешивает "навечно" функцию со всеми объектами).

• "defer …" не в том месте (когда для чего-то часть кода выносится в goroutine, можно напортачить).

• Создание "асинхронного" объекта во внешнем модуле (вот как "signal.Notify()") без явной его зачистки.

Ну, вот и всё.

Приветствуется конструктивная критика и тыканье пальцем "где я дурак".

Пользуясь случаем, всех с наступающим 2021 годом!