Go: фокусы трассировки

Введение

Доброго времени суток!

Гошка знатна не только простотой реализации многопоточности, но и мощными встроенными инструментами мониторинга и тестирования. Одним из таких инструментов является трассировка. На эту тему есть множество статей. Казалось бы, что здесь обсуждать? Случится авария — выполнишь несложную команду, и всё станет понятно. Тем не менее, получить трассировку — полдела. Необходимо ещё её правильно понять, т.к. некорректное восприятие может, в лучшем случае, вызвать некоторое недоумение, а в худшем — привести к ошибочным выводам и, как следствие, к многочасовому поиску источника проблемы. Конечно, во всём можно разобраться, но аварийные ситуации обычно требуют оперативного решения проблемы — времени учиться понимать трассировку не будет.

Трассировка

Прежде, вспомним о способах получения трассировки:

1. Средствами пакета runtime/trace

2. Тест

В обоих случаях трассировка будет записываться в файл trace.out. При использовании пакета runtime/trace необходимо добавить код, который создаст файл и запишет туда трассировку:

package main  import ( "os" "runtime/trace" "time" )  func main() { f, _ := os.Create("trace.out") defer f.Close() trace.Start(f) defer trace.Stop()  for i := 0; i < 100; i++ { go print(0) print(1) }  time.Sleep(500 * time.Microsecond) }

После запуска программы:

go run main.go 

в терминал будет выведен результат, который в данный момент не интересен, а также создастся файл trace.out. Далее необходимо выполнить команду:

go tool trace trace.out

После чего в stdout будет выведено:

2024/12/02 16:31:27 Preparing trace for viewer... 2024/12/02 16:31:27 Splitting trace for viewer... 2024/12/02 16:31:27 Opening browser. Trace viewer is listening on http://127.0.0.1:60612

Автоматически откроется страница http://127.0.0.1:60612. Для просмотра трассировки необходимо открыть http://127.0.0.1:60612/trace:

Тест позволяет не вносить правки в код, что в большинстве случаев важно, но его необходимо написать. Никогда не приходилось писать unit на функцию main 🙂 Поэтому, наверное, создам отдельную функцию:

func someFunc() { for i := 0; i < 100; i++ { go print(0) print(1) }  time.Sleep(500 * time.Microsecond) }

И тест для неё:

func TestSomeFunc(t *testing.T) { someFunc() }

Тестирование, конечно, получается символическим, т.к. ничего не проверяется. Тем не менее, тест позволяет получить трассировку. Для этого необходимо запустить его следующим образом:

go clean --testcache && go test -v ./... -run=TestSomeFunc --trace trace.out

При этом в stdout будет выведен результат:

=== RUN   TestSomeFunc 1111111... PASS: TestSomeFunc (0.00s) PASS ok  app0.012s

а также создастся файл с трассировкой trace.out, т.к. был передан флаг —trace с указанием имени файла trace.out. При открытии новой трассировки получим:

Фокус №1

После того, как вспомнили способы получения трассировки, самое время не просто посмотреть на графики, но ещё и понять, что там изображено. Но, как говорил Ювенал: «panem et circenses» — люди требуют «хлеба и зрелищ», поэтому спешу показать один фокус. Для этого рассмотрим следующий код:

func someFunc() { ch := make(chan int) for i := 0; i < 100; i++ { go func() { <-ch }() }  time.Sleep(time.Microsecond) }

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

func TestSomeFunc(t *testing.T) { someFunc() }

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

А что, если немного изменим код рассматриваемого примера?

func someFunc() { ch := make(chan int) for i := 0; i < 100; i++ { go func() { <-ch }() }  time.Sleep(2 * time.Millisecond) } 

Вместо микросекунды будем ждать 2 миллисекунды.

ВНИМАНИЕ! Сейчас будет фокус… убавилось освещение в зале, барабанная дробь…лёгкий холодок в груди. Кто-то из читателей нетерпеливо облизывает пересохшие губы…дамы в предобморочном состоянии…запускаем!

go clean --testcache && go test -v ./... -run=TestSomeFunc --trace trace.out

Бам! Открываем трассировку!:

Дамский визг! Слёзы!…глухие удары головами об пол от обморочных падений… возмущение, негодование господ! — читатели в смятении.

А что, собственно, произошло? А произошло следующее, вместо «стены» горутин наблюдаем горку — всего лишь небольшой всплеск. И если вот здесь поставим метку (указано чёрной стрелкой):

то убедимся, что нет ни одной горутины. А если нет горутин, то нет и утечки. Что за фокусы?! — возмутятся читатели. Ведь утечка должна быть!

Разоблачение

Для понимания этого фокуса требуется вспомнить GMP модель. О ней написано достаточно много материала. Можно здесь освежить память. Там достаточно подробно описано, с разноцветными картинками. Здесь лишь напомню основные моменты:

• в Go есть свой m:n планировщик

• среда выполнения Go имеет 2 вида очередей: локальная, глобальная

• горутины запускаются и выполняются исключительно в тредах

Также напомню о значении аббревиатуры GMP:

G — горутина

M — тред

P — логический процессор

Каждый P имеет свою локальную очередь из G. Также каждому P соответсвует конкретный M, в котором конкурентно запускаются G из соответствующей локальной очереди. При выполнении кода:

go func(){   ... }()

создаётся новая горутина G или берётся существующая из пула. Далее планировщик принимает решение о планировании, при котором G может переходить в разные статусы: waiting, running, runnable; по ним можно понять, что происходит с конкретной G. Спящие или заблокированные G попадают в глобальную очередь со статусом waiting. Running означает, что G выполняется в соответствующем M. Runnable — нахождение G в локальной очереди одного из P.

На рис. 6 поставлена метка в виде чёрной стрелки. При этом в нижнем окне видна информация: runnable = 39, running = 2. Вспомнив о GMP, понятно, что 39 горутин находятся в локальных очередях, а 2 — запущены в параллельных тредах. Т.е. какая картина получается? После выполнения:

go func() { <-ch }()

создаётся горутина, которая помещается в локальную очередь одного из P. Далее она запускается в соответствующем М. Выполняется логика:

<-ch

Т. к. канал пустой, горутина блокируется. И вот здесь, для понимания театра дальнейших действий, необходимо вспомнить, что заблокированные таким образом горутины оказываются в глобальной очереди в статусе waiting. Более того, они не используют тред в таком состоянии. Если внимательно посмотреть на рис. 6, то можно заметить, что горутины с таким статусом в трассировку не попадают — есть только runnable, running и GCWaiting. Соответственно, трассировка показывает только те горутины, которые выполняются в тредах, находятся в локальных очередях или ожидают выполнение GC (GCWaiting). Именно поэтому на рис. 5, при утечке ожидающих горутин, трассировка их не показала.

Фокус №2

А теперь рассмотрим другой пример:

package main  import ( "fmt" "os" "runtime/trace" "time" )  func main() { f, _ := os.Create("trace.out") defer f.Close() trace.Start(f) defer trace.Stop()  go func() { fmt.Println("start") for { for i := 0; i < 100000; i++ { fibonacci(0, 1, 80) } time.Sleep(100 * time.Millisecond) } }()  fmt.Println("Введите имя:") var n string fmt.Scan(&n) fmt.Println("Hello,", n, "!") time.Sleep(400 * time.Millisecond) }  func fibonacci(prev, current, n int) { if n == 0 { return } n--  fibonacci(current, current+prev, n) }

В представленном коде также снимается трассировка:

f, _ := os.Create("trace.out") defer f.Close() trace.Start(f) defer trace.Stop()

Далее запускается дочерняя горутина:

go func() { fmt.Println("start") for { for i := 0; i < 100000; i++ { fibonacci(0, 1, 80) } time.Sleep(100 * time.Millisecond) } }()

которая в бесконечном цикле имитирует «серьёзные» вычисления — 100 000 раз запускает рекурсивную функцию fibonacci, определяющую первые 80 чисел ряда, начиная с 0. За ненадобностью полученные числа никуда не выводятся. Далее дочерняя горутина приостанавливает своё выполнение на 100 миллисекунд. Помимо запуска дочерней горутины:

fmt.Println("Введите имя:") var n string fmt.Scan(&n) fmt.Println("Hello,", n, "!") time.Sleep(400 * time.Millisecond)

главная предлагает пользователю ввести имя в терминале. Т.е. блокируется, пока пользователь что-нибудь не напечатает. После ввода имени в терминале появляется фраза «Hello, <имя>!». Далее происходит задержка на 400 миллисекунд для более наглядной трассировки. Что логично ожидать? — дочерняя горутина даст одиночные ступеньки, т.к. главная большую часть времени будет находиться в статусе waiting, потому что либо заблокируется ожиданием ввода, либо уснёт на 400 миллисекунд. Самое время запустить код, причём с GOMAXPROCS = 1 для простоты восприятия:

GOMAXPROCS=1 go run main.go

и посмотреть на трассировку:

Если поставить метку после ввода данных пользователем:

то можно подумать, что я зря трачу время читателей, т.к. видим ожидаемый результат — с некоторой периодичностью появляется одиночная ступенька. А вот если до ввода данных в терминале:

то возникают вопросы — одиночной ступеньки не наблюдается. В трассировку также попадает главная горутина. Но ведь она же заблокирована. Как можно объяснить такое поведение? — дело в том, что только спящие или заблокированные в процессе коммуникации (блокировка каналами, мьютексами) горутины «паркуются» в глобальной очереди в статусе waiting. Если же речь идёт о блокировке в рамках операций ввода/вывода (рассматриваемый случай), других системных вызовах или вызове функций, не относящихся к функциям Go, то горутина продолжает оставаться в статусе running, более того, она продолжает использовать тред. И, вроде, всё становится понятно, но если обратим внимание на треды:

то увидим, что в трассировку попадает только один тред, в котором выполняется дочерняя горутина:

Что получается? — опечатка в литературе, или я что-то напутал?… Нет, такое странное поведение объясняется тем, что тред главной горутины отвязывается от логического процессора, т.е. вместо G-M-P получается G-M. Это сделано, чтобы не происходило блокировки выполнения других горутин при ожидании ввода/вывода и других системных вызовов. В этом и заключается причина, по которой такие треды не видны в трассировке. Тем не менее, без понимания, что из себя представляет Proc 0, такое объяснение может показаться неубедительным, ведь отвязанный от логического процессора тред продолжает выполняться на физическом ядре. Но вот здесь подвох — Proc 0 является логическим процессором. Он существует только в среде выполнения Go. Также следует иметь в виду, что GOMAXPROCS определяет максимальное количество логических процессоров, по умолчанию оно совпадает с количеством физических ядер… Конечно, практика более богата на примеры, тем не менее, при понимании, что именно попадает в трассировку, можно найти ответ на любой вопрос.

Как быть?

Горутина — это не просто действие, запуск некоторой логики. А это некоторая структура, которая при создании помещается в кучу. Стек ожидающей горутины нужно тоже где-то хранить. Поэтому, даже при неиспользовании треда, утечка горутин в статусе waiting неминуемо приведёт к утечке ресурсов. Возникает вполне естественный вопрос: а как отслеживать такие горутины?… Как вариант, можно воспользоваться решением от Uber. Оно, правда, требует написание теста, но это лучше, чем разочаровываться из-за наивной веры в «авось пронесёт». Ещё раз смоделируем эту коварную ситуацию:

package main  import ( "time" )  func someFunc() { ch := make(chan int) go func() { <-ch }()  time.Sleep(time.Second) }

Напомню тест для рассматриваемой функции:

package main  import ( "testing" )  func TestSomeFunc(t *testing.T) { someFunc() } 

Он по-прежнему ничего не тестирует, но используется для получения трассировки:

которая по-прежнему не отображает горутины в статусе waiting, что заставляет немного изменить код теста:

package main  import ( "testing"  "go.uber.org/goleak" )  func TestSomeFunc(t *testing.T) { defer goleak.VerifyNone(t)  someFunc() }

Добавлен вызов функции VerifyNone библиотеки go.uber.org/goleak. После запуска теста:

go clean --testcache && go test -v ./... --run=TestSomeFunc --trace trace.out

получим:

=== RUN   TestSomeFunc     main_test.go:41: found unexpected goroutines:         [Goroutine 10 in state chan receive, with app.someFunc.func1 on top of the stack:         app.someFunc.func1()         /usr/local/go/src/app/main.go:10 +0x24         created by app.someFunc in goroutine 9         /usr/local/go/src/app/main.go:9 +0x6c         ] --- FAIL: TestSomeFunc (1.49s) FAIL FAILapp1.509s FAIL 

Тест упал, сообщив о неожиданном нахождении горутины. После корректировки кода функции someFunc в виде добавления закрытия канала ch:

package main  import ( "time" )  func someFunc() { ch := make(chan int) go func() { <-ch }()  time.Sleep(time.Second) close(ch) }

снимается блокировка дочерней горутины, что приводит к устранению утечки и, как следствие, успешному прохождению теста:

=== RUN   TestSomeFunc --- PASS: TestSomeFunc (1.02s) PASS ok  app1.040s

Итого

• В трассировке указываются логические процессоры, а не физические ядра: Proc 0, Proc 1,… Proc n

• В трассировку попадают треды, выполняющие горутины и связанные с логическими процессорами

• В трассировку не попадают горутины в статусе waiting

• Для отслеживания утечек горутин в статусе waiting можно воспользоваться библиотекой go.uber.org/goleak