线上golang grpc服务资源泄露问题排查

前几天告警群里报出一个go服务grpc接口出现很多超时现象，排查发现是服务有内存泄露与cpu占用高的问题，在这里将排查的过程记录一下，给大家提供排查问题的方向与思路，同时借鉴教训，优化自己服务代码。

发现超时现象后，登录机器看了下top，该服务总共有两台机器，发现02机器的cpu与内存占用很高（如下图第一个进程），而01机器都很低。

正常情况下不会有这么高的资源占用，可能是服务有资源泄露的问题，资源一致得不到释放。

首先做的，是重启服务，优先解决问题，资源泄露的问题可以通过重启来快速解决，重启后接口超时现象不再出现，接口耗时恢复正常。

重启后，开始排查问题，超时的服务是B服务，上游有A服务调用B服务，从A服务中找了几个超时的请求，根据opentracing生成的tracer_id查询日志，发现A服务调用B服务超时5s就返回错误了，B服务收到了A服务的请求，发现有两种情况，一种是B立即收到了A的请求，但是处理了400+秒才返回；另一种是A发出请求400+秒后，B才开始处理请求。

另外发现grpc请求全部打到一台机器上，另一台机器没什么量。

然后去看了下历史cpu、内存曲线，发现cpu在15分钟内上升至很高，同时内存占用很高的现象。

拉长了内存统计时间，发现A服务的内存在缓慢增长，肯定是有内存泄露的问题：

总结下观察到的问题：

• 请求为什么全部打到一台机器上，两台机器的前面是有slb的，难道slb没有发挥作用吗？
• cpu占用在15分钟快速增长的原因是什么？
• 请求处理时间慢的原因是什么？
• 为什么会有内存泄露现象出现？

Q1 slb没有负载均衡

原因

针对Q1，特意去查了下slb的配置，由于slb是根据权重轮询的，可能权重配置错误导致的请求分配不均，但是看了配置，slb的配置并没有问题，两台后端服务器的权重相同。

然后去查了下，发现我们的slb是4层（tcp/udp层）的负载均衡，4层的slb是针对连接做负载均衡的，而不是针对请求，当连接的客户端很少时，负载也可能不均衡，4层的负载均衡是客户端和服务器tcp直连。

然后去两台机器上netstat看了下，发现01机器没有A服务的连接，02机器有A服务的连接。同时grpc维持的是长连接并且复用连接，对于新请求不会新建连接，这样在第一次经过slb的负载均衡创建连接后，grpc的请求会复用这个连接，请求会全部打到连接的机器上。

如何解决？

知道原因了，那么如何解决呢？可以通过etcd与grpc两者结合来实现服务注册与服务发现，grpc客户端根据所有server的ip来实现负载均衡。

Q2 cpu快速增长

原因

对于Q2，由于当时服务没有设置pprof，无法看到运行的状况……后面加了pprof，又不能马上复现，所以暂时是通过看代码的方式来猜测哪些地方可能出了问题- -

想到之前的请求处理了400+秒，并且当时内存占用很高，代码中又有worker类的任务，每秒从数据库中取出数据，对每条数据启动一个goroutine处理。

伪代码如下：

for {
	datas := Mysql.GetDatas()
	for _, v := range datas {
		cur := v
		go func() {
			handle(cur)
		}
	}
	time.Sleep(time.Second)
}

正常情况下，这是没问题的，但是当时机器的内存占用接近100%，那么goroutine的处理时间肯定变长，如果处理时间超过1秒甚至远超一秒，那么这个goroutine还没处理完，worker又新起了一个goroutine，goroutine的数量没有控制，多了以后又占用更多资源，旧的goroutine处理时间更长，worker还是每秒启动一个新的goroutine……后面就产生了goroutine泄露，这可能是导致cpu增长的主要原因。

所以初步猜测是内存泄露问题，导致内存占用很高，然后导致goroutine处理时间过长，又导致goroutine泄露，goroutine进一步导致cpu、内存增长。

后来在线上加了pprof，但是内存泄露比较缓慢，需要等一段时间才能捕获，到时候在这里补充。

如何解决？

对于goroutine泄露的解决，自然是控制goroutine的数量，我把伪代码改成了如下来控制goroutine（判断超过限制数量就sleep）：

int32 runningG = 0
const maxRunningG = 200
for {
	if atomic.LoadInt32(&runningG) > maxRunningG {
		time.Sleep(time.Seconds * 3)
		continue
	}
	datas := Mysql.GetDatas()
	for _, v := range datas {
		cur := v
		atomic.AddInt32(&runningG, 1)
		go func() {
			handle(cur)
			atomic.AddInt32(&runningG, -1)
		}
	}
	time.Sleep(time.Second)
}

Q3 请求处理缓慢

原因

处理请求缓慢的原因可能是Q2 goroutine泄露问题导致的cpu占用过高，请求处理不过来了。

如何解决？

参考Q2解决方案

Q4 内存泄露问题

原因1

同样也是直接从代码的角度排查，借鉴了网上一些人的内存泄露经验，发现一个方法中对于http请求的处理方式可能有问题。

对于每个http请求，该方法每次都会新建一个http.Client与transport, 伪代码如下。

...
tr := &http.Transport{
   TLSClientConfig: &tls.Config{
      ... // 证书相关
   },
}
client := &http.Client{Transport: tr}
response, err := client.Post(url, contentType, body)
if err != nil {
   return
}
responseByte, err := ioutil.ReadAll(response.Body)
if err != nil {
   return
}
...

而通过http.Client与transport的注释我们可以看出这两个是可以复用的。

http.Client:

// The Client's Transport typically has internal state (cached TCP
// connections), so Clients should be reused instead of created as
// needed. Clients are safe for concurrent use by multiple goroutines.
//

http.Transport:

// Transports should be reused instead of created as needed.
// Transports are safe for concurrent use by multiple goroutines.

且该方法对于http.Response.Body没有调用**Close()**方法，这可能导致潜在的资源泄露。

如何解决？

创建全局的http Client和Transport并且设置好超时时间等参数，复用这个client。http请求返回的response需要调用http.Response.Body.Close()释放连接使其可以被其他协程复用。

原因2

同时发现对于mysql查询结果的处理，也可能有些问题，伪代码如下：

rows, err := db.Query(sql, case)
if err != nil {
	return
}
for rows.Next() {
	if err = rows.Scan(...); err != nil{
		return
	}
	...
}

对于sql.Query的结果rows，如果没有rows.Close()，但是rows.Scan()读取了所有的数据，那么rows的资源会自动得到释放；

但是如果Scan发生错误，rows没有读取完，又没有rows.Close()，就可能导致潜在的内存泄露。

如何解决？

每次都调用rows.Close()方法来释放资源。

rows, err := db.Query(sql, case)
if err != nil {
	return
}
defer rows.Close() //
for rows.Next() {
	if err = rows.Scan(...); err != nil{
		return
	}
	...
}

其他原因

通过pprof正在分析中…… 待补充。

总结

以上为个人经验，希望能给大家一个参考，也希望大家多多支持脚本之家。

最新评论