前言

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

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

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者不止是有无缓冲的区别，还有同步异步的差别。