线上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服务的内存在缓慢增长,肯定是有内存泄露的问题:
在这里插入图片描述
总结下观察到的问题

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

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正在分析中…… 待补充。