Введение
Доброго времени суток!
Гошка знатна не только простотой реализации многопоточности, но и мощными встроенными инструментами мониторинга и тестирования. Одним из таких инструментов является трассировка. На эту тему есть множество статей. Казалось бы, что здесь обсуждать? Случится авария - выполнишь несложную команду, и всё станет понятно. Тем не менее, получить трассировку - полдела. Необходимо ещё её правильно понять, т.к. некорректное восприятие может, в лучшем случае, вызвать некоторое недоумение, а в худшем - привести к ошибочным выводам и, как следствие, к многочасовому поиску источника проблемы. Конечно, во всём можно разобраться, но аварийные ситуации обычно требуют оперативного решения проблемы - времени учиться понимать трассировку не будет.
Трассировка
Прежде, вспомним о способах получения трассировки:
Средствами пакета runtime/trace
Тест
В обоих случаях трассировка будет записываться в файл 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 app 0.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
FAIL app 1.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 app 1.040sИтого
В трассировке указываются логические процессоры, а не физические ядра: Proc 0, Proc 1,... Proc n
В трассировку попадают треды, выполняющие горутины и связанные с логическими процессорами
В трассировку не попадают горутины в статусе waiting
Для отслеживания утечек горутин в статусе waiting можно воспользоваться библиотекой go.uber.org/goleak
