记一次 grpc 短连接未关闭导致的资源泄漏问题的排查过程

文章简介：记一次 grpc 短连接未关闭导致的资源泄漏问题的排查过程

问题现象

正在欢快的写 bug 的时候，测试师傅突然呼叫我说一个测试环境的 cpu 90%+, 内存 10GB(超出预期太多)。赶紧登录到机器上看下现场。

问题排查过程

首先使用 fgprof 看下当前比较耗时的代码逻辑在哪里：

1
2
3

export ENDPOINT=http://localhost:9699

go tool pprof -http=:8081 ${ENDPOINT}/debug/fgprof

图中可以看到 grpc.Server 相关的时间时间比较多。此图可以反映出慢处理路径。但看到 grpc server 慢，不能反映出是 grpc server 处理慢。

其次看 profile：

1

go tool pprof -http=:8081 "${ENDPOINT}/debug/pprof/profile?seconds=30"

此图反映出业务占用 On-CPU 时间 37%，在努力消费 kafka 中的数据； 30% cpu 在执行 runtime.gcBgMarkWorker，其他时间占比比较少，可忽略。37%时间消耗在消费 kafka 消息中，这个符合预期，这个业务主要做消费 kafka 中的数据。30% 的 runtime.gcBgMarkWorker 执行逻辑从名字可以看出，在执行 gc 的逻辑；runtime.scanobject 占用了 30%的时间，大量时间消耗在 gc 上，猜测是有内存泄漏.

查看 heapdump 中的 inused_objects：

1

go tool pprof -http=:8081 ${ENDPOINT}/debug/pprof/heap

从图中可以看到 grpc.DialContext/grpc.(*addrConn).resetTransport 函数执行路径分配了过多内存。grpc.DialContext 的作用是创建 grpc 连接，grpc.(*addrConn).resetTransport 是 http2 连接保活. 查看当前 goroutine stacktrace，多少函数调用栈包含 resetTransport 即表示当前进程有多少 grpc 连接.

恐怖的 20348，并且在持续的增大.

问题可以大胆猜测，由于 kafka 消费过程中每个消息执行一次 service.SendNoticeCallBack, 每次掉用 grpc 创建连接 rpcclient.NewMsgDogServiceGrpcClient， 而没有关闭连接，导致大量的连接持续后台保活，grpc 连接过多对象过多导致 gc 时间过多，内存占用多。

基于这个假设，查看这个grpc客户端对应的服务端的连接状态:

服务端连接也基本与上边的客户端连接数对的上。

解决办法

先简单打个 patch，找到 service.SendNoticeCallBack 函数，把 rpcclient.NewMsgDogServiceGrpcClient 返回的 grpc 连接在使用完后及时关闭。

长期解决办法: 即grpc复用连接，在初始化应用的时候初始化一个 grpc 连接，作为依赖传递给此函数，使用的时候直接使用创建好的连接掉用服务.