go脚本阻塞问题排查

前言

前几天一个同事突然找我说线上的一个定时脚本跑着跑着不退出了,这种情况也不是必现,不过出现的概率还是很高的,于是叫我帮忙排查。当时我一听到故事背景,心里想这指不定是哪里堵塞了。按照以往经验,有可能是网络请求没设置超时时间、死循环、死锁、或者其他堵塞。

已知排查这类问题的方法:

  1. 查看代码或者打印日志,缩小范围(最无奈之举,兜底方案,有时候可能非常有效)
  2. 借助工具

准备

本文采用第二种方式:借助工具。下面是常用“道具”:

  1. net/http/pprof (on-cpu)
  2. github.com/felixge/fgprof (off-cpu)

正常一次性脚本,执行时间是短暂,应该用runtime/pprof来收集运行时数据分析。但是本次是一个堵塞的脚本,故可用net/http/pprof进行分析,而且方便远程访问。net/http/pprof针对线程花费在CPU上的时间进行分析即on-cpu。经常pprof都和fgprof配合使用。
      简单添加几行代码,重新编译,部署,执行脚本。

分析

由于k8s集群未将9091端口开放,故用常规命令kubectl port-forward进行端口转发,然后在浏览器上进入http://127.0.0.1:9091/debug/pprof/ 界面,如下:

可以看到block 和mutex都正常。按照之前的猜想,肯定得看goroutine,那就直奔主题,一般协程泄漏或者堵塞都是看这的。进去看看每个协程都在干啥?如下图:

可以看出现在总共有55协程,其中12个协程是在执行/usr/local/go/src/database/sql/sql.go:1052 这行代码。刷新几次浏览器,发现所有协程仍然还是在执行这些代码。前面几十个协程正在执行的代码都比较常规,并没有发现异常。 再往下看发现clickhouse相关代码,问了同事,其实脚本中并没有使用clickhouse,那估计是不小心被引入了。继续看,重头戏来了。

这里明确的出现了业务代码(图中打码位置),是amqp相关的代码。问了同事,说也是不小心引入的,其实脚本并不需要。这就完全不能忽视了。对比下代码,发现这是一段程序退出时释放资源的代码(defer cleanup())。这是一个很重要的信息。根据调用链,看到目前协程正在执行sync.runtime_SemacquireMutex 这行代码,且刷新几次网页,发现还是这几行代码。runtime_SemacquireMutex是什么呢?之前看过sync.Mutex源码,这是利用信号量挂起一个协程的操作。再结合我们在退出程序资源释放是同步的,也就是说如果资源释放卡住的话,会导致程序卡住。所以说这很可能就是导致程序堵塞住的原因。有了这么个可疑点,当然不能放过,继续探究,看到底是释放哪个资源。仔细看上图,发现是下图的816行,如下图所示:

session.Close()是在一个闭包函数内,为了让外面可以主动关闭amqp的连接。外部调用如下图:

这么一想,runtime_SemacquireMutex导致主程序堵塞就更顺理成章了。加个日志,验证一波,防止误杀。

看下pod日志

至此知道罪魁祸首的是amqp释放资源堵塞住了,也经过验证了。本来这个脚本就不需要用到amqp,是因为不小引入的,所以脚本代码只需稍作修改就能解决问题。但本次问题排查并没有结束,继续刨根问底(不想看导致amqp释放资源堵塞的原因剖析的话,可以跳过直接看结论吧)。

刨根问底

为什么引入了amqp就会有这个问题呢?这个脚本中出现了这个问题,那么线上其他使用该amqp方法的项目会不会也有这个问题?这个问题产生的真实原因是什么呢?需要解决问题,还是得复现。根据脚本的情况,很容易得出复现方案:启动amqp,但是不往amqp中发送消息,过几秒后关闭amqp连接即上面的session.Close()。写个demo,很容易就复现了。还是需要看这部分

上面看得出来调用顺序: shutdown->sync.Once.Do 然后就被lock住了。Do执行的方法是

c.destructor.Do(func() {
    c.m.Lock()
    defer c.m.Unlock()
    if err != nil {
        for _, c := range c.closes {
            c <- err 
        }
    }
    //省略无关代码
    ...
    c.channels = map[uint16]*Channel{}
    c.allocator = newAllocator(1, c.Config.ChannelMax)
    c.noNotify = true
} 

其中c.destructor的类型为sync.Once结构体。都知道sync.Once的参数f是只会被执行一次的,但是sync.Once可以被调用多次。那么为什么这个地方会被锁住呢?只有一种可能性,那就是:sync.Once不止被调用1次,第一次调用一直没有退出,导致后面的调用被lock了。经过调试发现395行堵塞了。关键性代码如下:

393   if err != nil {
394      for _, c := range c.closes {
395          c <- err  //出现堵塞
396     }
397  } 

熟悉channel的话,都知道以下几种情况会导致堵塞:1.有缓冲channel写满 2.无缓冲channel没有接受者 3. 往一个nil的channel写数据。具体是哪种情况,还需进一步定位,然后对c.closes一探究竟。经过调试得到一个惊天大发现,如下:

图中的amqp.Error是一个channel结构,其字段dataqsiz为缓冲最大数量,0表明该channel是无缓冲的。继续往下看recvq是一个空的双向链表(recvq是等待接收的goroutine组成的双向链表),那么意味着这个无缓冲channel没有接收者,而395行又往 channel里面放数据,所以必然导致堵塞。
      图中的buf显示这个channel的类型是 github.com/streadway/amqp.Error。那么在封装的amqp驱动里面搜索一下amqp.Error,就发现notifyChanClose和notifyConnClose这2个用于接收Connection closed和Channel closed通知的channel,以及他们的初始化:

如上图,这2个channel确实是无缓存的。notifyConnClose通道的接收数据代码如下:

for {
//省略无关代码
...
169 	select {
170 	case <-sess.done:
171   		return true
172 	case <-sess.notifyConnClose:
173   		log.Println("Connection closed. Reconnecting...|", sess.config.QueueName)
174   		return false
175 	case <-sess.notifyChanClose:
176   		log.Println("Channel closed. Re-running init...|", sess.config.QueueName)
	}
}

当前session.Close()会执行close(sess.done),sess.done就会接收到通知,从171行退出for循环,进而整个协程退出,导致notifyConnClose这个channel没有协程接收数据(对应着上图中的recvq为nil)。此时若有协程给notifyConnClose发送数据,就会被堵塞住。至此算是完全知道原因了,后续直接将2个channel改成缓冲为1的channel就解决问题了。

总结

  1. 在写依赖注入时,需要明确本服务需要哪些驱动,尽量不引入没有用到的驱动。
  2. pprof的goroutine可以很好的分析协程泄漏,协程堵塞这类问题。
  3. 在使用channel时需考虑清楚到底用有缓冲还是无缓冲的,2者不止是有无缓冲的区别,还有同步异步的差别。