【踩坑日记】一次goroutine泄露问题的排查定位
问题的发现
前段时间，我们一个基于libbeat开发的日志采集服务经常发生OOM的告警，OOM的排查大都比较简单，直接查看目标容器的内存变化情况即可。如图所示
从上图可以看出，内存随着时间呈线增长的趋势，然后在到达阈值之后瞬间降为0，实际上就是OOM了。
相信稍微有点经验的同学，应该都能大致断定这是个内存泄露的问题了。而Go程序的内存泄露大部分则都是goroutine泄露导致的。
画外音
这里，若你的程序并没有接入监控，那么也可以通过vmstat工具来人工观察内存的变化情况。不管怎样，我们需要的是能观察到内存随时间的变化情况。
问题代码段定位
既然知道了问题的大致方向，那自然也就有了排查思路了。
首先，既然是用Go编写的应用程序，那么很自然，我们就应该想到pprof工具，它会动态跟踪记录程序运行过程中的各项参数，并提供各种工具图表来帮助你定位问题，功能强大又好用。这里，如果你对pprof工具还不熟悉的，建议先行阅读官方文档或者Google一些入门教程。
接着，我通过添加启动参数--pprof，来激活预置的pprof端口服务。通常，我们会预置类似下面代码块，以便在出现问题的时候，激活pprof功能。
import _ "net/http/pprof"
...
func main() {
...
if cfg.Pprof {
http.ListenAndServe(":6060", nil)
}
...
}
修改完成后，我重启了docker容器。并在容器中执行curl http://localhost:6060/debug/pprof/heap > h1.out以及curl http://localhost:6060/debug/pprof/goroutine > g1.out命令获取heap和goroutine的信息。这里由于是排查内存问题，我就取了heap和goroutine的数据。
在间隔30分钟后（这个取决于内存的增长速率），我再次执行curl http://localhost:6060/debug/pprof/heap > h2.out以及curl http://localhost:6060/debug/pprof/goroutine > g2.out命令。
这里，我为什么要间隔30分钟取两次样本数据呢？还是因为我们需要的是变化情况，而非当前状态，这很关键。
内存泄露的原因有很多，比如http body未Close，channel阻塞导致goroutine泄露等等。
因此，首先需要排查一下是不是其他非goroutine泄露的原因导致内存泄露，我首先执行go tool pprof --base h1.out h2.out，进入交互界面，然后执行top10、web等命令。很不幸，我并没有发现什么异常。
随后，就是需要排查goroutine泄露了，执行go tool pprof --base g1.out g2.out，接着我执行top5命令，发现runtime.gopark积累了很多，然后我使用了traces命令，发现是Next.func1goroutine异常地多，使用list Next.func1发现，在71行有1315个goroutine阻塞了，在通过web检查也是同样的情况。很显然是这快代码有问题。那么究竟是什么原因导致的呢？
PS
上图是我后面在本地压测复现时的图，当时排查生产环境时未截图记录，因此后续大家排查的时候一定要记录好。方便后续复盘、回顾所用。
根因探究
看似，我们的重点都在问题的发现以及问题代码段定位上了，然而在我看来熟悉了上面排查思路以及pprof等工具的使用后，还是相对比较容易定位的。
而根因的探究，则需要你对应用程序的源码很熟悉才行，网上的教程由于用的都是很简单的demo，因此看起来似乎很容易就解决了，然而实际代码往往非常的庞大而复杂。因此这一步，需要你对应用程序的源码比较熟悉，这样才能快速准确的找到问题背后的原因。
实际上，由于我才接手这一块，在这一步上也卡了很久。最终，通过反复阅读源码和设计文档，并且与社区深度讨论之后，定位到了原因。
简单来说，这是由于这里的goroutine是依赖于第70行返回的err来判断并退出的，然而，由于在日志采集相关goroutine在执行关闭操作的过程中，有新的message被采集并发送到r.ch上，而此时从r.ch上消费的逻辑已暂停，从而即便后续关闭操作执行完成，r.reader.Next()返回错误，也会阻塞在第71行。具体想了解的可以查阅这个issue。
可以看出，有效可靠地关闭goroutine是多么的重要，稍不留神就泄露了。
文章主要是记录了一次实际goroutine泄露的发现-排查-根因定位的全过程。对工具的介绍和使用，基本不涉及，你可以通过查阅其他资料学习
