目录
因实际生产过程中涉及流程较多,排查起来需层层排除,步步为营,最终实现找到罪魁祸首。但当你真真正正解决了问题时,你的心情是放松的、愉悦的!
有两个程序A和B,A会和B建立grpc连接,A端通过封装来管控建立的所有连接, 正常情况下A和B均一直启动着。
其中与B程序一样的还有几个在其它机器上,也就是A和C、D等都可能会建立连接。
当意识到发生协程泄漏时,百感交集,这又是一个考验干部的机会,机不可失!
程序运行过程中,发现协程数一直在上涨,一开始只有五十个左右,随着时间变化经过了几个小时后,一度涨到1900左右,同时A的常驻内存也在持续上涨。
此时分析出现的日志,发现后台在不断的建立连接和断联操作,每次两个操作之间间隔了大概几十秒的样子。
分析图如下(此时协程数为1878):
可以看出不存在其它代码的协程泄漏,发现goroutine占的较多的是grpc相关的第三方包,大协程数均出现在了grpc这块(这句话你看到后是不是有了些想法?) grpc本身也是构建在HTTP/2之上的。
查询当前top20,结合此图,我们能看到这几样子关键调用(取重要部分,copy时顺序已乱):
internal/poll.runtime_pollWait
internal/poll.(*pollDesc).waitRead (inline)
internal/poll.(*pollDesc).wait
internal/poll.(*FD).Read
google.golang.org/grpc.(*addrConn).resetTransport
google.golang.org/grpc.(*ccBalancerWrapper).watcher
google.golang.org/grpc/internal/transport.(*controlBuffer).get
google.golang.org/grpc/internal/transport.(*loopyWriter).run
google.golang.org/grpc/internal/transport.newHTTP2Client.func3
google.golang.org/grpc/internal/transport.(*http2Client).reader
看看源码中涉及transport及resetTransport的地方:
而resetTransport里最后进行了阻塞,直到resetTransport为down才会解除阻塞,也就是说对应的goroutine一直得不到释放,此处已发生泄漏
由pprof图得知resetTransport那里堆积了376个goroutine,不就是这里么。
简单说下为什么一直在建联和断连
这和逻辑有关。排查已在维护的客户端时会进行遍历,一旦发现某些客户端不合法、连接为空等情况时会主动做断连操作,而一直在反反复复进行这两个操作就不对劲了,后来排查发现是代码问题,在初始化每个连接时一切都是成功的,但在注册到维护的map时没有赋值(疏漏),因此实际上每次检测连接时就会将其断掉(调用自己封装客户端的close方法)。
而断掉的逻辑是怎样的呢?
判断每个客户端对应的grpc连接,如果连接不为空则进行close()并删掉维护的相关记录,为空当然直接清除记录即可就不需要conn.close,基于上面的情况,赋值就没有赋上,因此close的时候当然每次conn都是空的了,可怕的是这时候它的连接实际上还正常着,也就是说经过close后没有成功的close掉、连接还在…
这样一直往复,就导致和目标服务建立了很多个grpc连接却想关闭而没有实际关闭,一直建联、一直上涨。
再来验证一下分析的结果:
在目标机器上netstat当前建立的tcp连接,发现从A连到B的连接大量堆积,都是ESTABLISHED状态的连接。
正常情况下,A到B理论上只会有一个正常的连接,这一看就不对,这样下去fd、内存就耗完了!
这下不就清楚了?那我们再来通过外围连接层面试试,将B直接停掉,看看A的协程数是不是大幅降低?(此时在B上检查, 和A建立的tcp连接达300多个,A协程数此时为1947)
经过试验,直接降低57%左右,从1947 降到 835
(为什么不是直接降低到接近正常的数量,一是因为同时还有其它到A的连接,二是外部断联后,部分受grpc管控的,猜测像
controlbuffer, balancewapper, loopyWriter 以及socket相关的pollwait等相关routine或流程并没有停止或立即停止所致,最后修复后多次重复相关操作,并未出现上述几个关键模块的泄露现象,后者需深究源码及相关流程)
观察几个小时后,协程数一直维持在830左右,不再上涨,这也就印证了排除此部分的问题外,其它部分不存在goroutine泄漏, 此时只需要解决此问题即可。
根据分析的情况重新修改代码,正确赋值、确保每次正常关闭,再次重启并试验整个过程,结果正常,无异常上涨!
多次重复相关过程,得到的分析图如下:
可以看到很清爽,持续观察没有冗余不断暴涨的现象。
因时间紧迫,这次也以解决问题为主要目的,花了一些时间层层排查到了这里,找到原因可以松一口气了!