go语言死循环分析

发表于 | 分类于

最近看了一篇文章，如何定位 golang 进程 hang 死的 bug，里面有这样一段代码：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
package main
import (
    "fmt"
    "io"
    "log"
    "net/http"
    "runtime"
    "time"
)
func main() {
    runtime.GOMAXPROCS(runtime.NumCPU())
    go server()
    go printNum()
    var i = 1
    for {
        // will block here, and never go out
        i++
    }
    fmt.Println("for loop end")
    time.Sleep(time.Second * 3600)
}
func printNum() {
    i := 0
    for {
        fmt.Println(i)
        i++
    }
}
func HelloServer(w http.ResponseWriter, req *http.Request) {
    fmt.Println("hello world")
    io.WriteString(w, "hello, world!\n")
}
func server() {
    http.HandleFunc("/", HelloServer)
    err := http.ListenAndServe(":12345", nil)
    if err != nil {
        log.Fatal("ListenAndServe: ", err)
    }
}

运行，会发现打印一会儿数字后停了，我们执行

1
curl localhost:12345

程序卡死。关于程序挂在哪里借助dlv是很好定位的：

1
dlv debug hang.go

进去之后运行程序，打印停止进入卡死状态，我们执行ctrl C，dlv会显示断开的地方：

1
2
3
4
5
6
7
8
9
10
11
12
13
received SIGINT, stopping process (will not forward signal)> main.main() ./hang.go:17 (PC: 0x12dd7c8)
    12: func main() {
    13:         runtime.GOMAXPROCS(runtime.NumCPU())
    14:         go server()
    15:         go printNum()
    16:         var i = 1
=>  17:         for {
    18:                 // will block here, and never go out
    19:                 i++
    20:         }
    21:         fmt.Println("for loop end")
    22:         time.Sleep(time.Second * 3600)
(dlv)

但是我还是不明白，不明白的地方主要是因为：

  • 我又看了两篇文章Goroutine调度实例简要分析和也谈goroutine调度器，是同一位作者Tony Bai写的，写得非常好。第二篇文章解释了goroutine的调度和cpu数量的关系（不多加解释，建议大家看看），我的mac是双核四线程（这里不明白的同学自行google cpu 超线程），go版本是1.9，理论上讲可以跑4个goroutine而不用考虑死循环，一个死循环最多把一个cpu打死，上面的代码中只有3个goroutine，而且他们看上去都挂住了。
  • 上面说的理论上讲，不是我主观臆测的，我跑了1中第一篇文章中的一个例子:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
package main
import (
    "fmt"
    "time"
)
func deadloop() {
    for {
    }
}
func main() {
    go deadloop()
    for {
        time.Sleep(time.Second * 1)
        fmt.Println("I got scheduled!")
    }
}

上面代码有两个goroutine，一个是main goroutine，一个是deadloop goroutine，跑得时候deadloop gouroutine不会对main goroutine造成影响，打印一直在持续，作者的文章解释了原因。

在如何定位 golang 进程 hang 死的 bug有这样一段话：

因为在 for 循环中没有函数调用的话，编译器不会插入调度代码，所以这个执行 for 循环的 goroutine 没有办法被调出，而在循环期间碰到 gc，那么就会卡在 gcwaiting 阶段，并且整个进程永远 hang 死在这个循环上。并不再对外响应。

这个其实就是我们的第一段代码卡死的原因，也是我们第二段代码没有卡死的原因，就是在gc上！

我们再看一篇文章，golang的垃圾回收（GC）机制，这篇文章很短，但每句话都很重要：

  1. 设置gcwaiting=1，这个在每一个G任务之前会检查一次这个状态，如是，则会将当前M 休眠；
  2. 如果这个M里面正在运行一个长时间的G任务，咋办呢，难道会等待这个G任务自己切换吗？这样的话可要等10ms啊，不能等！坚决不能等！
    所以会主动发出抢占标记（类似于上一篇），让当前G任务中断，再运行下一个G任务的时候，就会走到第1步

那么如果这时候运行的是没有函数调用的死循环呢，gc也发出了抢占标记，但是如果死循环没有函数调用，就没有地方被标记，无法被抢占，那就只能设置gcwaiting=1，而M没有休眠，stop the world卡住了（死锁），gcwaiting一直是1，整个程序都卡住了！

这里其实已经解释了第一份代码的现象，第二份代码为什么没有hang住相信大家也能猜到了：代码里没有触发gc！我们来手动触发一下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
package main
import (
    "fmt"
    "log"
    "net/http"
    _ "net/http/pprof"
    // "runtime"
    "time"
)
func deadloop() {
    for {
    }
}
func main() {
    go func() {
        log.Println(http.ListenAndServe("localhost:6060", nil))
    }()
    go deadloop()
    i := 3
    for {
        time.Sleep(time.Second * 1)
        i--
        fmt.Println("I got scheduled!")
        if i == 0 {
            runtime.GC()
        }
    }
}

会发现打印了3行之后，程序也卡死了，bingo🎉

我们来看看gcwaiting是不是等于1:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
$ go build hang2.go
$ GODEBUG="schedtrace=300,scheddetail=1" ./hang2
SCHED 2443ms: gomaxprocs=4 idleprocs=3 threads=7 spinningthreads=0 idlethreads=2 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=1 schedtick=4 syscalltick=5 m=5 runqsize=0 gfreecnt=1
  P1: status=0 schedtick=14 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  P2: status=0 schedtick=3 syscalltick=4 m=-1 runqsize=0 gfreecnt=0
......  
SCHED 2751ms: gomaxprocs=4 idleprocs=0 threads=7 spinningthreads=0 idlethreads=2 runqueue=0 gcwaiting=1 nmidlelocked=0 stopwait=1 sysmonwait=0
  P0: status=1 schedtick=4 syscalltick=5 m=5 runqsize=0 gfreecnt=1
  P1: status=3 schedtick=14 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  P2: status=3 schedtick=3 syscalltick=10 m=-1 runqsize=0 gfreecnt=0
  P3: status=3 schedtick=1 syscalltick=26 m=0 runqsize=0 gfreecnt=0
  M6: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 helpgc=0 spinning=false blocked=false lockedg=-1
  M5: p=0 curg=19 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 helpg

代码诚不欺我也！

参考资料