如何排查Go服务假死问题

问题引入

  不知道你有没有遇到过这种情况：Go服务看起来正在运行，但是大量HTTP请求却没有任何响应，甚至查不到任何业务日志。我们通常称这一现象为Go服务假死。

  造成Go服务假死的原因有很多种，比如死锁。也就是说，请求处理协程抢占了一把已被其他协程占有并且永远不会释放的锁时，这时候所有的请求处理协程都将被无限期阻塞，Go服务当然也就不会有任何响应了。

  本文主要讲解如何排查Go服务中的假死问题。

工欲善其事，必先利其器

  如何排查Go服务中的假死问题？当然需要一些工具了，总不能靠猜吧。Go语言官方提供了一款非常强大的性能分析工具pprof，它可以收集Go程序的各项运行时指标数据，包括内存、CPU、锁等。有了这些指标数据，大部分Go服务性能问题（如死锁）都可以迎刃而解。

  当然，要想通过pprof分析程序性能，需要引入一点点代码，如下所示：

package main
import (
    "net/http"
    _ "net/http/pprof"
)
func main() {
    go func() {
        http.ListenAndServe("0.0.0.0:6060", nil)
    }()
}
// http://127.0.0.1:6060/debug/pprof/

  接下来，只需要访问指定地址（如上所示），即可获取Go程序的各项运行时指标数据。pprof总共提供了9种类型的运行时指标，如下所示：

• allocs: 内存分配情况的采样数据
• block: 采集因为同步原语而阻塞的协程调用栈，默认不开启；可通过runtime.SetBlockProfileRate开启
• cmdline: 程序启动命令
• goroutine: 采集所有协程的调用栈
• heap: 同allocs指标，可用来采样存活对象的内存分配情况（可通过参数gc=1在采样前运行GC）
• mutex: 采集持有互斥锁的协程调用栈，默认不开启；可通过runtime.SetMutexProfileFraction开启
• profile: CPU采样，可以通过参数seconds设置采样时间，该指标需要使用pprof工具分析
• threadcreate: 采样创建线程的调用栈
• trace: 采样当前程序的执行轨迹，可以通过参数seconds设置采样时间，该指标需要使用trace工具分析

  可以看到，pprof工具可以用来分析内存溢出问题、协程溢出问题、锁/阻塞问题等。那么如何应用这些数据指标呢？举一个例子，指标goroutine可以采集所有协程的调用栈，通常可以用来分析Go服务的阻塞情况，比如当大量协程阻塞在获取锁的代码时，那是不是有可能是因为锁没有被释放？比如当大量协程阻塞在写管道的代码时，那是不是有可能是因为读管道的协程太慢或者异常退出了？goroutine指标的输出内容如下所示：

// goroutine指标地址
http://127.0.0.1:6060/debug/pprof/goroutine?debug=1
// 第一个数字表示协程数
1 @ ……
#    0x1063928    internal/poll.runtime_pollWait+0x88        /go1.18/src/runtime/netpoll.go:302

  参考上面的输出结果，每一个协程调用栈的第一行中的第一个数字都表示协程数，即当前有多少个协程处于这样的协程调用栈。如果你发现这个数字非常大，说明当前有较多协程因为同一个原因而阻塞，并且很有可能这就是Go服务响应慢或者没有响应的原因。另外可以看到，协程调用栈包括整个调用链的函数或者方法名称以及文件行号，这些信息足以帮助我们分析问题产生原因。

小试牛刀

  如何排查HTTP状态码504问题（请求超时）呢？通常我们首先会查看业务日志，通过业务日志分析服务到底慢在哪里。那如果查询不到任何业务日志呢？是不是能说明服务压根就没有接收到客户端请求呢？其实也不一定，笔者就曾经遇到过这么一个事例：Go服务部署在容器平台，某一时刻突然出现大量HTTP状态码504，初步排查发现查询不到请求对应的业务日志。难道是客户端与容器之间的链路存在异常？
  登录该容器实例，手动通过curl命令发起的HTTP请求（请求健康检查接口），发现竟然也没有任何响应。这就奇怪了，健康检查接口的逻辑非常简单，按理说不应该超时。与此同时，使用工具tcpdump抓取请求数据包，如下所示：

$ curl http://xxxx/v1/healthCheck
//三次握手
10:20:21 IP xxxx.40970 > server.8080: Flags [S], length 0
10:20:21 IP server.8080> xxxx.40970: Flags [S.], length 0
10:20:21.941175 IP xxxx.40970 > server.8080: Flags [.], length 0
//发送HTTP请求数据
10:20:21 IP xxxx.40970 > server.8080: Flags [P.], ength 311
10:20:21 IP server.19001 > xxxx.8080: Flags [.], length 0
// 阻塞，无响应

  参考上面的输出结果，可以明显看到当客户端与Go服务建立TCP连接并发起HTTP请求之后，Go服务一直没有返回HTTP响应。为什么Go服务明明已经接收到HTTP请求了，却没有任何响应呢？联想到我们的Go服务都开启了pprof，可以先简单看一下服务统计指标，如下所示：

curl http://127.0.0.1:xxxxx/debug/pprof/
<td>16391</td><td><a href=goroutine?debug&#61;1>goroutine</a></td>
……

  参考上面的输出结果，协程数量非常多，甚至有1.6万多，要知道这只是一个灰度服务，访问量其实是比较小的，不应该有这么多协程。继续使用工具pprof查看协程统计信息，如下所示：

$ go tool pprof http://127.0.0.1:xxxxx/debug/pprof/goroutine
(pprof) traces
----------+-------------------------------------------------------
7978 runtime.gopark
     runtime.goparkunlock
     runtime.chansend
     runtime.chansend1
     xxxxx/log4go.(*FileLogTraceWriter).LogWrite
    ……

  参考上面的输出结果，总共有7978个协程都因为同一个原因被阻塞了。继续分析协程调用栈，发现是HTTP请求处理协程在记录日志时，由于写管道被阻塞了。接下来就容易多了，只需要分析日志库的代码逻辑，基本就能确定问题原因了。

如何实现非阻塞读写管道

  上述示例表明， HTTP请求处理协程在记录日志时，写管道被阻塞了，这才导致服务假死了。有什么办法能彻底避免这一问题吗？想想web服务，写日志是必然的同时也是非必须的，如果可以通过非阻塞方式写管道，是不是就能彻底避免阻塞问题？

  select + default的组合还可以实现管道的非阻塞操作，参考下面代码：

package main
import (
    "fmt"
    "strconv"
)
func main() {
    queue := make(chan int, 0)
    for i := 0; i < 10; i ++ {
        select {
        case queue <- i:
            fmt.Println("insert: " + strconv.Itoa(i))
        default:
            fmt.Println("skip: " + strconv.Itoa(i))
        }
    }
}

  变量queue是无缓冲管道，理论上后续的写入操作都会阻塞用户协程。但是如果执行上面的程序，你会发现主协程并没有阻塞，而是循环输出了 skip: xxx，这说明select语句执行的是default分支。为什么写管道没有阻塞主协程呢？参考Go源码中的一段注释，如下所示：

// 编译器实现
// select + default语法如下：
//    select {
//    case c <- v:
//        ... foo
//    default:
//        ... bar
//    }
// 编译器转化后的代码如下
//    if selectnbsend(c, v) {
//        ... foo
//    } else {
//        ... bar
//    }
//
// 函数selectnbsend的实现如下：
func selectnbsend(c *hchan, elem unsafe.Pointer) (selected bool) {
    return chansend(c, elem, false, getcallerpc())
}

  参考上面的代码，函数runtime.chansend第三个输入参数是bool类型：true表示如果不可写，阻塞用户协程；false表示始终不阻塞用户协程。另外，如果写管道执行成功，返回的也是true，此时执行的就是if分支，否则执行else分支（对应的就是default分支）。

总结

  生产环境总是会遇到一些千奇百怪的问题，比如Go服务总是时不时地响应非常慢甚至完全没有响应，比如Go服务的内存占用量总是居高不下等。所以，Go程序性能分析的基本手段还是需要掌握的，否则在遇到性能问题时你将束手无策。