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

一时失言乱红尘 2023-07-21 05:49 29阅读 0赞

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

发现超时现象后，登录机器看了下top，该服务总共有两台机器，发现02机器的cpu与内存占用很高（如下图第一个进程），而01机器都很低。  
正常情况下不会有这么高的资源占用，可能是服务有资源泄露的问题，资源一致得不到释放。首先做的，是重启服务，优先解决问题，资源泄露的问题可以通过重启来快速解决，重启后接口超时现象不再出现，接口耗时恢复正常。  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2xpeXVubG9uZzQx_size_16_color_FFFFFF_t_70]  
重启后，开始排查问题，超时的服务是B服务，上游有A服务调用B服务，从A服务中找了几个超时的请求，根据opentracing生成的tracer\_id查询日志，发现A服务调用B服务超时5s就返回错误了，B服务**收到了**A服务的请求，发现有两种情况，一种是B立即收到了A的请求，但是处理了400+秒才返回；另一种是A发出请求400+秒后，B才开始处理请求。

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

然后去看了下历史cpu、内存曲线，发现cpu在15分钟内上升至很高，同时内存占用很高的现象。  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2xpeXVubG9uZzQx_size_16_color_FFFFFF_t_70 1]![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2xpeXVubG9uZzQx_size_16_color_FFFFFF_t_70 2]  
拉长了内存统计时间，发现A服务的内存在缓慢增长，肯定是有内存泄露的问题：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2xpeXVubG9uZzQx_size_16_color_FFFFFF_t_70 3]  
总结下观察到的问题

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

### Q1 slb没有负载均衡 ###

#### 原因 ####

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

然后去查了下，发现我们的slb是4层（tcp/udp层）的负载均衡，4层的slb是**针对连接**做负载均衡的，而不是针对请求，当连接的客户端很少时，负载也可能不均衡，4层的负载均衡是客户端和服务器tcp直连。  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2xpeXVubG9uZzQx_size_16_color_FFFFFF_t_70 4]

然后去两台机器上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正在分析中…… 待补充。

[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2xpeXVubG9uZzQx_size_16_color_FFFFFF_t_70]: /images/20230528/429cea8a17ec41b7a2f56ca247568627.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2xpeXVubG9uZzQx_size_16_color_FFFFFF_t_70 1]: https://img-blog.csdnimg.cn/20200402165623180.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2xpeXVubG9uZzQx,size_16,color_FFFFFF,t_70
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2xpeXVubG9uZzQx_size_16_color_FFFFFF_t_70 2]: /images/20230528/898b49769d0149f98a97ec0c7cbc299d.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2xpeXVubG9uZzQx_size_16_color_FFFFFF_t_70 3]: /images/20230528/b8ea2a718a80431298124c9f30dd2f10.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2xpeXVubG9uZzQx_size_16_color_FFFFFF_t_70 4]: /images/20230528/27d99680b3024187beb6d27d704bd992.png