排查goroutine泄漏

在golang中创建goroutine很容易，但不合理的使用可能会导致大量goroutine无法结束，无法释放资源，久而久之造成内存泄漏。避免goroutine泄漏的关键是妥善管理goroutine的生命周期。通过导出运行时指标并使用pprof，可以发现并解决goroutine泄漏。作者维护了一个服务，通过SSH连接到目标机器并执行命令。这是一个小的内部服务，平时没问题的时候我是不会去关注的。大约4个月前，在上次更新的时候，添加了一个taskcounter，并导出到prometheus进行监控。最近，发现这个计数器在稳步增加。第一反应是，好东西！来电数量稳步上升！！但是我觉得不对，这个小小的内部服务哪里来这么多调用。于是查看goroutine的监听情况（这个数据是从runtime.NumGoroutine()中获取的）。goroutines的数量也在稳步增长。单位时间内的请求数增加了，goroutines的数量也增加了。没有什么问题。但是转念一想，小的内部服务是不可能的。于是查看mm系统中所有请求的视图：可以看到请求量大约是每5分钟2000个左右，平均请求量是每分钟400个。在上面的prometheus监控图中，每条曲线都是一个实例。实际上deployment有4个instance，所以400要除以4才能得到单instance的请求量（曲线）应该在100/min左右，服务时计数器确实在100/min左右刚刚开始，随着时间的推移慢慢泄露。Goroutine泄漏（Goroutineleak）虽然我认为99%都是泄漏，但是还是需要看一些详细的资料。net/http/pprof之前在服务中开启过，所以直接请求pprof暴露的HTTP接口。#Goroutinessummarycurlhttp://service:port/debug/pprof/goroutine?debug=1#Goroutinesdetailscurlhttp://service:port/debug/pprof/goroutine?debug=2先看导出的goroutine总结：有1000+个goroutine处于同一个状态，简单的看等待读取数据，再看导出的goroutine详情：不知道没看到，看到就惊呆了，有详细信息（4个月）中是否有goroutines阻塞超过200,000分钟...肯定是goroutine泄漏。为什么会漏水？只能按照pprof导出的goroutine信息查看。打印出1000多个处于IO等待最多状态的goroutine的调用栈。根据这个调用栈的内容，找到对应代码的位置。从ssh.Dial到某个地方，io.ReadFull会被阻塞。向上。此服务使用golang.org/x/crypto/ssh包进行ssh连接。先看这个服务调用ssh.Dial的地方：clientConfig:=&ssh.ClientConfig{...Timeout:3*time.Second,...}//connettosshclient,err:=ssh.Dial("tcp",fmt.Sprintf("%s:%d",s.Host,36000),clientConfig)好像没什么问题，毕竟传入了一个Timeout参数，应该不会被阻塞。然后继续看下去，发现了一些问题。直接到调用栈中阻塞的地方（抛开library和runtime，这两个一般没问题），就是SSHHandshake的第一步，交换SSH版本的步骤。//Sendsandreceivesaversionline.TheversionLinestringshould//beUSASCII,startwith"SSH-2.0-",andshouldnotincludea//newline.exchangeVersionsreturnstheotherside'sversionline.funcexchangeVersions(rwio.ReadWriter,versionLine[]byte)(them[]byte,errorror){...if_,err=rw.Write(append(versionLine,'\r','\n'));err!=nil{return}them,err=readVersion(rw)returnthem,err}//maxVersionStringBytes是我们将接受的最大字节数//接受版本字符串.RFC4253section4.2limitsthisat255//charsconstmaxVersionStringBytes=255//ReadversionstringasspecifiedbyRFC4253,section4.2.funcreadVersion(rio.Reader)([]byte,error){versionString:=make([]byte,0,64)varokboolvarbuf[1]byteforlength:=0;length10.100.7x.x9:36000(ESTABLISHED)#ls-l/proc/33027/fd/16lrwx-----1mqqmqq64Dec2315:44/proc/33027/fd/16->socket:[3069826111]执行这条命令的时间是24号17:25，已经封锁了一天多。这里的问题是应用层没有超时控制。回过头来看ssh.Dial的逻辑，在SSH握手的时候并没有使用Timeout参数作为超时控制参数。net.Conn的IO等待在Linux下是通过非阻塞的epoll_pwait实现的。等待的goroutine会被挂起，直到有事件进来。超时通过设置定时器来处理，唤醒goroutine。暴露的接口是net.Conn的SetDeadline方法，所以我重写了ssh.Dial的逻辑，在SSHhandshake阶段增加了一个超时时间：//DialTimeoutstartsclientconnectiontothegivenSSHserver.Differfrom//ssh.Dialfunction,thisfunctionwillbetimeoutwhendoingSSHhandshake.//totaltimeout=(1+timeFactor)*config.Timeout//refs:https://github.com/cybozu-go/cke/pull/81/filesfuncDialTimeout(network,addrstring,config*ssh.ClientConfig)(*ssh.Client,error){conn,err:=net.DialTimeout(network,addr,config.Timeout)iferr!=nil{returnnil,err}//settimeoutforconnectiontimeFactor:=time.Duration(3)err=conn.SetDeadline(time.Now().Add(config.Timeout*timeFactor))iferr!=nil{conn.Close()returnnil,err}//doSSHhandshakec,chans,reqs,err:=ssh.NewClientConn(conn,addr,config)iferr!=nil{returnnil,err}//取消连接read/writetimeouterr=conn.SetDeadline(time.Time{})iferr!=nil{conn.Close()returnnil,err}returnssh.NewClient(c,chans,reqs),nil}把ssh.Dial换成这个函数后，编译上线，查看连接状态，恢复正常（恢复到一个小服务该有的样子）#netstat-anp|grep:36000|awk'{print$6}'|sort|uniq-c3ESTABLISHED1LISTEN86TIME_WAIT这里你会发现，其实本文解决的问题是如果peer出现各种异常如何及时关闭连接，而不是解决异常的问题同行。毕竟SSH不正常，谁能上去查问题。现网服务器数量庞大，运行状况各不相同。所以，有异常在情理之中，一一解决是不现实的。最后，当我第一次发现泄漏时，我走到机器顶部看了看。当时，我被50G的VIRT职业震惊了。在群里咨询过老大（zorro），其实这个值大部分时候不需要关注。只关心RES占用率。因为RES是实际占用的物理内存。此时只看VIRT和RES，无法看出泄漏了多少。只能与不同时间点的内存使用情况进行比较。比如问题解决后，运行三四天，VIRT占用3.9G，而RES只占用16M。这样一来，还是释放了很多内存。或者那些可以看到泄漏的goroutine占用了多少内存。在golang中创建goroutine非常容易，但是不合理的使用可能会导致大量的goroutine无法结束，无法释放资源，久而久之造成内存泄漏。避免goroutine泄漏的关键是妥善管理goroutine的生命周期。通过prometheus/client_golang导出运行时指标，使用net/http/pprof查找和解决goroutine泄漏。【本文为专栏作者《腾讯技术工程》原创稿件，转载请联系原作者（微信ID：Tencent_TEG）】点此查看该作者更多好文