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

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

    Нюанс

    Замечу, что поисковик google судя по всему "сопротивляется" "нубским" запросам. Потому что после некоторого "обучения" с уточняющими формулировками в ответ на "базовый" поиск "golang pprof" начало появляться кое-что интересное. Например, статья довольно известного автора.

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

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

    Мотивация

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

    • И ещё. Возможно, знатоки подскажут в комментариях, до какой степени (порядок величин) безопасно плодить "сирот" в go. Что-то подсказывает мне, что goroutines не обладают свойством бесконечно малой нагрузки на местный шедулер…

    Забегая вперёд, для профилирования достаточно периодически куда-нибудь писа́ть "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()") без явной его зачистки.

    Версии софта

    Отладка проводилась под go1.14. Но в целом всё справедливо как минимум с версии 1.8. И статически слинкованный бинарник под 1.8 будет процентов на 30 легче. Если не нужны последние фичи.

    От желания попробовать go1.15 пришлось воздержаться. Потому что пробравшиеся хипстеры резко сломали поддержку X.509 "CommonName" при проверке сертификатов. (Традиционно) не зная, что кроме публичного Интернет есть ещё всякие "закрытые" сегменты, с высокими лагами по внесению изменений.

    Ну, вот и всё.

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

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

    Похожие публикации

    Реклама
    AdBlock похитил этот баннер, но баннеры не зубы — отрастут

    Подробнее

    Комментарии 21

      0
      1. Не совсем понятно — у вас приведенная горутина (To complete report processing even after return on timeout) вызывается в каком-то цикле, что утечка накапливается?
      2. Обычно после «получения» сигнала программа так или иначе завершается, поэтому примеры кода в документации приведены на этот самый простой распространенный кейс.
      3. Как правило, сигналы «ловят» на уровне main или близком к нему — в функцию обычно передают и работают с контекстом (context.Context).
      4. Вместо done <- struct{}{} в большинстве случаем можно и принято использовать close(done).
        0
        1. Конечно. И по п.2 статьи можно оценить интенсивность (известно число провисших объектов и примерное время).
        2. Да. Но чтобы завершиться, неплохо бы корректно закрыть запущенные (форки, треды, корутины, горутины) нужное подчеркнуть. В go мне показалось проще подписаться на готовую сигнализацию «os.Signal». Я не прав? → п.3
        3. Ага, спасибо. Раз «так принято», есть смысл в дальнейшем перестроиться (чтобы не мешать сопровождающим код).
        4. Спасибо. Так действительно будет лучше читаться.
          –1
          Если программа завершает работу, то какими-то завершающими действиями можно пренебречь, если они не влияют на результат. Например, csv writer лучше всё-таки зафлашить, а соответствующий открытый файл закрыть. Но конкретно с сигналами я никогда не видел код, который бы явно вызывал Stop имено для того, чтобы устранить утечку, потому что все равно программа тут же закрывается.

          С контекстом было бы примерно так:
          func main() {
          	ctx, cancel := context.WithCancel(context.Background())
          	defer cancel()
          
          	signals := make(chan os.Signal, 1)
          	signal.Notify(signals, syscall.SIGHUP, syscall.SIGINT, syscall.SIGKILL, syscall.SIGTERM)
          
          	go func() {
          		<-signals
          		fmt.Println("cancel")
          		cancel()
          	}()
          
          	done := make(chan struct{})
          
          	go func() {
          		for {
          			select {
          			case <-ctx.Done():
          				close(done)
          				return
          			}
          		}
          	}()
          
          	<-done
          	fmt.Println("exit")
          }
          
            +1
            Не вижу приемуществ от использования контекстов, кроме замены
            case exitSignal = <-signals: на case <-ctx.Done():
            Вот если спрятать логику чтобы была отдельная функция
            func doYourStuff(ctx context.Context) <-chan struct{} {
            	done := make(chan struct{})
            	go func() {
            		for {
            			select {
            			case <-ctx.Done():
            				close(done)
            				return
            			}
            		}
            	}()
            	return done
            }
            0
            «Самопальный» timer возможно тоже стоит заменить на context.WitdDeadline() или context.WithTimeout()
              0
              Почему бы и нет, раз есть готовое. Вопрос кругозора пишущего код.
              • Вот Вы мне его (кругозора) и добавили. Хотя, есть нюанс. Если велосипед не тяжёлый, бывает смысл его реализовать без привлечения большого комбайна. В целях, так сказать, неувеличения энтропии. У меня вот там два типа сигнализации: тик и таймаут. Не думаю, что привлечение «context» сильно разгрузит код.
                0
                Не вникал в код, но мне кажется, вам бы подошли стандартные Ticker и Timer. При этом это были бы локальные объекты для вашей горутины, и не нужно было бы использовать глобальную синхронизируемую коллекцию таймеров.
                Для устранения «недочетов» оформления кода и вообще на этапе ознакомления с языком можно использовать возможности IDE — например, GoLand (хотя он платный, но есть EAP/trial).
                В дополнение к проверкам IDE есть линтеры. github.com/golangci/golangci-lint включает большой их набор, но по-умолчанию включены не все.
                  0
                  С контекстами есть такая проблема, что они не дают возможности управлять порядком завершения компонентов, а также отследить момент, когда они все успешно завершаться. Примерно как если бы вы заглянули в комнату, крикнули «эй, завершитесь!», и пошли дальше, не интересуясь, что там дальше будет (ломанутся ли они все вместе одновременно в дверь, начав конфликтовать, очнутся ли только через сутки и тд и тп).
                  Я не так давно писал статью об том, как это делать: habr.com/ru/company/vivid_money/blog/531822
                  Думаю, вы сможете переиспользовать какие-то паттерны из последнего рассмотренного мной подхода.
                0
                2. Использовать close(done) не просто удобно, но и в таких случаях не произойдет возможной утечки памяти. И скорее всего вам нужен defer close(done) в начале функции. Это обычный паттерн когда «producer» рутина работает с каналами.

                Так и не понял была ли утечка связанная с commands.UUID или нет. «Вроде бы так можно, т.к. в этот момент переменная не „зачищена“ и должна быть скопирована в defer.».
                Не очень понимаю что значит «зачищена», но вроде бы в таких случаях переменная будет аллоцирована в heap и код прозрачно для вас будет работать с указателем. Как и в случаях когда переменная утекает из функции
                func () {
                    v := 0
                    return &v
                }
                  0
                  Я, когда утверждал «Вроде бы так можно», руководствовался вот этим (но «по памяти», отсюда prepend «Вроде»):
                  Each time the «defer» statement executes, the function value and parameters to the call are evaluated as usual and saved anew but the actual function is not invoked.

                  Я это понимаю как «любой defer создаёт функцию с аргументами, вычисляемыми (в данном случае, копируемыми) в момент задания (а не исполнения) defer». Поправьте, если у Вас другая версия реальности.
                  Это не отменяет «мутности» данного кода, и так по моему мнению делать просто не нужно. Ну вот зачем изображать «асинхронное замыкание» на языке, всячески поощряющем «деревянное» программирование? Для скорости? Так defer сам по себе «дорогой».
              +1
              Запись в «занулённый» канал из ранее запущенной goroutine (завешивает «навечно» функцию со всеми объектами).

              Я бы порекомендовал книжку Concurrency in Go.
                0
                Опять golang… да это какая-то болезнь. Ну ведь Go же. Golang — это что-то из разряда Clang, Javalang, Pythonlang и т.д.
                  –1
                  В это трудно поверить, но надо признаться, что мне… как-то всё равно. Обзываю, как на язык ляжет.
                  • Удлинение слишком короткого слова — обычная у китайцев практика. Возможно, от них и пошло́.
                    –1
                    С го это чуть более оправданно, потому что слово слишком короткое и очень часто используется, и просто в разговорной речи и в названиях продуктов (pokemon go, amazon go, тд) в итоге что-то гуглить становится очень сложно. Пусть лучше уж golang, это более уникальное слово, сразу задаётся нужный контекст.
                      –1
                      А C или R не короткие? ))) Странное оправдание. Попробуйте на Youtube так же поискать информацию по Rust. Вам очень повезет, если вы встретите ролики именно по языку программирования, а не только стримы по одноименной игре. Вероятно, его тоже следует называть Rustlang, тем более что и официальный сайт тоже с приставкой lang, как и у Go. Но этого почему-то никто не делает. А так, наберите в Гугле Go, удивитесь, что он выдаст ссылки именно по Go. Никаких трудностей. Более того, часто ли вы ищете просто “Go”, “C” или “Java”? Полагаю, что чаще вы все-таки уточняете, что именно хотите найти, например, “Go goroutines” или еще более конкретно.
                        0

                        ну, чего ты докопался, в самом деле?

                          0
                          Я не докопался. Я просто хочу, чтобы человек, который себя позиционирует специалистом в языке, хотя бы называл его правильно. Ведь куча новичков читает и впитывает все это, а ведь многие реально так и считают, что язык называется именно так. И многие не понимают, что это все-лишь «прозвище».
                          0
                          > А так, наберите в Гугле Go, удивитесь, что он выдаст ссылки именно по Go
                          Вы же понимаете, что он выдаст вам ссылки именно по го, потому что вы скорее всего гуглили уже кучу программерских вещей и поэтому гугл догадывается, какой контекст вы ищете?
                          Думаю также, что с C или R тоже есть свои сложности, а также нет ничего плохого в том, чтобы называть язык так, как хочется, тем более, что это задаёт дополнительный контекст.
                          И да, кстати, домены для языков тоже называются golang.org и www.rust-lang.org вместо каких-нибудь go.it и rust.tech :)
                            0
                            я вам об этом выше и написал, что так называются сайты, но не сами языки. И ответьте тогда уж на вопрос, почему Rust никто не называет rustlang’ом? Его уважают больше или идиоты на нем не могут писать просто?
                            0

                            Про название: https://golang.org/doc/faq#go_or_golang


                            Про поиск:
                            image

                        0
                        Ура, опять видны все комментарии. Вчера во второй половине дня с хабром случилось нечто, «подрезавшее» всё кроме первых нескольких. Вероятно, в отдаваемом мне шарде. (С нескольких точек/браузеров показывало одну и ту же «фигу», хотя число в заголовке было похоже на правду.)
                        А я уже́ было приготовился «вытаскивать» из почты. Потому что толковые (а даже если не очень) замечания — мой «профит» от подготовленного материала.
                        Всех с наступающим! Пора готовиться к НГ.

                        Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

                        Самое читаемое