Aug
10
goroutine调度"导致"的一次事故
1. 现象
某日线上服务报警(基于时序数据库做的),请求量大幅下滑。
观察ganglia监控图表,发现有部分机器CPU占用率断崖式下跌,从原先的1000%+下降到100%(20核40线程的CPU),通过内存监控可以确认服务本身并未重启。
登录异常机器,用 lsof -i :PORT1 也可以看到端口号仍被占用,但是却无法接受请求;同样,该服务的 pprof 监听端口 PORT2 能接受请求,但无响应请求。
2. 排查
在异常机器上通过 "netstat -antpl | grep CLOSE_WAIT | grep PORT1 | wc -l" 可以看到有大量连接等待关闭,达到连接上限,所以无法接受请求,PORT2 则正常。
挑一台机器重启后服务恢复正常。为了恢复业务,重启了大部分异常机器上的服务,保留两台持续排查。
使用 top 查看cpu占用率,如上所述,始终保持在 100% 左右,说明有一个线程在全速运行。
通过 perf top (注:也可以使用pstack,能看到更详细的调用栈),发现是某一个二分查找的函数在占用cpu。
经过对代码的分析,发现是传入的值小于有效查找范围,代码实现不完善,导致出现了死循环。
进一步排查发现某个api未做好数据有效性保护,导致出现无效数据。
3. 分析
问题的直接原因已经定位,但是不明确的是,为什么一个 goroutine 死循环会导致进程整体hang住?
cpu 占用率只有100%,说明只有一个 goroutine 死循环,根据 Go 的 GMP 模型,理论上应该可以schedule其他的 goroutine 继续接受请求。
查看该进程的线程数(cat /proc/PID/status),看到开启了80+系统线程,说明不是线程数量的问题。
尝试查看该进程的 goroutine 数,但 pprof 不可用,而负责这个 metrics 打点的 goroutine 自从异常以后也未再上报数据。
写了一个简单的样例代码,开启一个简单死循环的goroutine,并不会阻碍其他goroutine的执行。
有一位同学根据现象搜到了这篇文章: 如何定位 golang 进程 hang 死的 bug
根据这篇文章的分析,在有死循环goroutine的情况下,其他goroutine主动调用 runtime.GC() 会出现 hang 住的情况。
验证代码如下,确实符合预期,和前述事故的表现一致。
综合以上分析可知,当 golang 中出现一个死循环的 goroutine、该 goroutine 就会一直占用 cpu,无法被调度;而需要 STW 的 gc 又无法暂停该 goroutine,因此出现了一个调度上的死锁。
另外,根据那篇文章的说法,在 for 循环中没有函数调用的话,编译器不会插入调度代码,所以无法完成抢占式调用。《深入解析Go - 抢占式调度》中也有具体的说明 https://tiancaiamao.gitbooks.io/go-internals/content/zh/05.5.html
实际测试发现,如果是调用自己写的另外一个简单函数,仍然会出现死锁,而调用注入 fmt.Println 之类的函数,则不会出现死锁,说明Go并不是在函数调用的时候插入调度检测代码(这也不符合直觉,每次函数调用都有额外性能开销,不太划算),而是在某些库函数中增加了调度检测。
完。
转载请注明出自 ,如是转载文则注明原出处,谢谢:)
RSS订阅地址: https://www.felix021.com/blog/feed.php 。
某日线上服务报警(基于时序数据库做的),请求量大幅下滑。
观察ganglia监控图表,发现有部分机器CPU占用率断崖式下跌,从原先的1000%+下降到100%(20核40线程的CPU),通过内存监控可以确认服务本身并未重启。
登录异常机器,用 lsof -i :PORT1 也可以看到端口号仍被占用,但是却无法接受请求;同样,该服务的 pprof 监听端口 PORT2 能接受请求,但无响应请求。
2. 排查
在异常机器上通过 "netstat -antpl | grep CLOSE_WAIT | grep PORT1 | wc -l" 可以看到有大量连接等待关闭,达到连接上限,所以无法接受请求,PORT2 则正常。
挑一台机器重启后服务恢复正常。为了恢复业务,重启了大部分异常机器上的服务,保留两台持续排查。
使用 top 查看cpu占用率,如上所述,始终保持在 100% 左右,说明有一个线程在全速运行。
通过 perf top (注:也可以使用pstack,能看到更详细的调用栈),发现是某一个二分查找的函数在占用cpu。
经过对代码的分析,发现是传入的值小于有效查找范围,代码实现不完善,导致出现了死循环。
进一步排查发现某个api未做好数据有效性保护,导致出现无效数据。
3. 分析
问题的直接原因已经定位,但是不明确的是,为什么一个 goroutine 死循环会导致进程整体hang住?
cpu 占用率只有100%,说明只有一个 goroutine 死循环,根据 Go 的 GMP 模型,理论上应该可以schedule其他的 goroutine 继续接受请求。
查看该进程的线程数(cat /proc/PID/status),看到开启了80+系统线程,说明不是线程数量的问题。
尝试查看该进程的 goroutine 数,但 pprof 不可用,而负责这个 metrics 打点的 goroutine 自从异常以后也未再上报数据。
写了一个简单的样例代码,开启一个简单死循环的goroutine,并不会阻碍其他goroutine的执行。
func test1() {
fmt.Println("test1")
i := 0
for {
i++
}
}
func main() {
go test1()
for i := 0; i < 100; i++ {
time.Sleep(1 * time.Second)
fmt.Printf("i = %d\n", i)
}
}
fmt.Println("test1")
i := 0
for {
i++
}
}
func main() {
go test1()
for i := 0; i < 100; i++ {
time.Sleep(1 * time.Second)
fmt.Printf("i = %d\n", i)
}
}
有一位同学根据现象搜到了这篇文章: 如何定位 golang 进程 hang 死的 bug
根据这篇文章的分析,在有死循环goroutine的情况下,其他goroutine主动调用 runtime.GC() 会出现 hang 住的情况。
验证代码如下,确实符合预期,和前述事故的表现一致。
func test1() {
fmt.Println("test1")
i := 0
for {
i++
}
}
func main() {
go test1()
for i := 0; i < 100; i++ {
time.Sleep(1 * time.Second)
fmt.Printf("i = %d\n", i)
if i == 3 {
runtime.GC()
}
}
}
fmt.Println("test1")
i := 0
for {
i++
}
}
func main() {
go test1()
for i := 0; i < 100; i++ {
time.Sleep(1 * time.Second)
fmt.Printf("i = %d\n", i)
if i == 3 {
runtime.GC()
}
}
}
综合以上分析可知,当 golang 中出现一个死循环的 goroutine、该 goroutine 就会一直占用 cpu,无法被调度;而需要 STW 的 gc 又无法暂停该 goroutine,因此出现了一个调度上的死锁。
另外,根据那篇文章的说法,在 for 循环中没有函数调用的话,编译器不会插入调度代码,所以无法完成抢占式调用。《深入解析Go - 抢占式调度》中也有具体的说明 https://tiancaiamao.gitbooks.io/go-internals/content/zh/05.5.html
实际测试发现,如果是调用自己写的另外一个简单函数,仍然会出现死锁,而调用注入 fmt.Println 之类的函数,则不会出现死锁,说明Go并不是在函数调用的时候插入调度检测代码(这也不符合直觉,每次函数调用都有额外性能开销,不太划算),而是在某些库函数中增加了调度检测。
完。
欢迎扫码关注:
转载请注明出自 ,如是转载文则注明原出处,谢谢:)
RSS订阅地址: https://www.felix021.com/blog/feed.php 。