一次gRPC使用不当导致goroutine泄漏排查记录
一次使用pprof工具定位和排查goroutine泄漏的实战记录。
由于保留必要的“罪证”，因此某些异常只能通过文字来描述了～
背景
昨晚上10点左右，前端童鞋反映开发环境接口响应超时，但过了几分钟后又恢复了，于是有了这一篇文章。
其实很久以前就出现了内存占用异常的情况～，只是占用并不高也就是50MB左右，加上当时还忙着写业务需求就没有急着加上pprof来检查。
首先通过运维平台(k8s based)直观发现了该pod数量从1变成了2, 再结合新增pod的启动时间，我发现该时间正好是前端童鞋反映状况的时间节点，稍后我检查了下该服务的资源限制如下图：
那么前端童鞋反映的问题就很明显了，由于某种原因导致了pod内存超限，触发了运维平台对于内存超限的“容忍机制”。表现为: 新增一个pod用于缓解服务压力，老服务由于无法申请更多内存会导致崩溃或其他异常（无法响应客户端请求），这与反映的情况一致。
pprof排查
知道了服务内存异常，想要具体定位的话，这时候就需要pprof上场了。
如果你需要重启服务才能开启pprof的话，那么只能等待复现了。这里我在开发环境和测试环境一直开启了pprof，因此可以直接检查。个人觉得，这样还可以帮助开发和测试，完成最初的性能分析😼。
内存检查
go tool pprof --http=:8080 https://service.host.com/debug/pprof/heap
这个命令是在本地打开一个web服务，直接可视化该服务的内存占用情况。也可以使用:
go tool pprof https://service.host.com/debug/pprof/heap 使用交互模式来分析。通过这个步骤定位到了 grpc相关的包内存占用异常分为两个部分：
50MB+ google.golang.org/grpc/internal/transport.newBufWriter
50MB+ bufio.NewReaderSize
http2 相关库的占用也比较多
这一切都指向了我们使用的gRPC，可是为啥使用gRPC会用到这么“多”内存呢？接着分析
goroutine检查
打开一看 https://service.host.com/debug/pprof/一看，goroutine和heap居“高”(4000+)不下，虽然对于动辄10W+的别人家的服务来说，这点根本不算事，但在我们这种小作坊里可就算异常了。点开看goroutine查看详情，有四个部分的goroutine分别有900个左右，这里就算初步定位了“gRPC客户端使用了较多的goroutine，但是却没有正确的结束掉”，如下图（这是解决后的截的图）：
pprof总结
服务中使用的gRPC客户端出了某些故障，导致了goroutine泄漏，引发了OOM（Out Of Memory）。如下图：
代码排查
上一步已经定位到是gRPC客户端的问题，那么就可以直接从代码上手了。我心里已经有一个“嫌疑犯”了，如下：
var (
defaultHandler *handler
timeout = 5 * time.Second
// _ pb.UserServiceClient = &handler{}
)
// Init of usersvc.handler
func Init(rpcAddr string) error {
// ... 略去不表
}
type handler struct {
// rpc configs
rpcAddr string
client pb.UserServiceClient
lastGrpcReqError error
}
func (h *handler) connectRPC() {
if h.client != nil && h.lastGrpcReqError != nil {
// 这里判断的本意是：如果客户端初始化失败，
// 或者期间因为异常情况，导致客户端与服务端连接中断的情况下尝试重连。
//
// 但是忽略了gRPC实现中，对于客户端的处理：
// 1. grpc.Dail 是异步的
// 2. grpc 有自己的重连机制
//
// 这一部分我还没有看完，就不乱发表看法了。
conn, err := grpc.Dial(h.rpcAddr, grpc.WithInsecure())
if err != nil {
logger.Std.Errorf("could not dial: %s with err: %v", h.rpcAddr, err)
return
}
logger.Std.Infof("usersvc.client.connectRPC called")
h.client = pb.NewUserServiceClient(conn)
}
}
// QueryBasicInfoByID based default Handler .
func QueryBasicInfoByID(in *pb.ByIDForm) (*pb.BasicInfoResponse, error) {
defaultHandler.connectRPC()
ctx, cancel := context.WithTimeout(context.Background(), timeout)
defer cancel()
resp, err := defaultHandler.client.QueryBasicInfoByID(ctx, in)
defaultHandler.lastGrpcReqError = err
return resp, err
}
抛开本意不谈，这样的写法也是不OK的。。。因为
if h.client != nil && h.lastGrpcReqError != nil {
// 经过初始化后的client始终不等于nil, 那么控制grpc.Dail的就只剩下了err,
// 而err的取值是所有的方法的报错，而不只是连接异常。
//
}
那么修复工作只需要 去除掉这“简陋破烂”的重连 就行了：注释掉所有跟connectRPC和lastGrpcReqError相关的代码行。
这里我还做了一个简单的测试，如下：
const N = 100
func Test_clientErr(t *testing.T) {
profileWriter, _ = os.OpenFile("./profile.normal.out", os.O_CREATE|os.O_WRONLY, 0644)
heapWriter, _ = os.OpenFile("./memprofile.normal.out", os.O_CREATE|os.O_WRONLY, 0644)
pprof.StartCPUProfile(profileWriter)
defer pprof.StopCPUProfile()
for i := 0; i < N; i++ {
// Normal err = nil
resp, err := QueryBasicInfoByID(&usrpb.ByIDForm{UserId: 1})
// 会触发 err = NotFound
// resp, err := QueryBasicInfoByID(&usrpb.ByIDForm{UserId: 11})
t.Log(resp, err)
}
runtime.GC()
if err := pprof.WriteHeapProfile(heapWriter); err != nil {
t.Error(err)
}
}
// 未修复前，100个NotFound错误
// Showing nodes accounting for 8040.19kB, 100% of 8040.19kB total
// Showing top 10 nodes out of 26
// flat flat% sum% cum cum%
// 5446.66kB 67.74% 67.74% 5446.66kB 67.74% google.golang.org/grpc/internal/transport.newBufWriter
// 1056.33kB 13.14% 80.88% 1056.33kB 13.14% bufio.NewReaderSize
// 513kB 6.38% 87.26% 513kB 6.38% golang.org/x/net/http2/hpack.newInternalNode
// 512.19kB 6.37% 93.63% 512.19kB 6.37% runtime.malg
// 512.01kB 6.37% 100% 1025.01kB 12.75% golang.org/x/net/http2/hpack.addDecoderNode
// 0 0% 100% 1025.01kB 12.75% golang.org/x/net/http2.(*Framer).ReadFrame
// 0 0% 100% 1025.01kB 12.75% golang.org/x/net/http2.(*Framer).readMetaFrame
// 0 0% 100% 1025.01kB 12.75% golang.org/x/net/http2/hpack.(*Decoder).Write
// 0 0% 100% 1025.01kB 12.75% golang.org/x/net/http2/hpack.(*Decoder).parseFieldLiteral
// 0 0% 100% 1025.01kB 12.75% golang.org/x/net/http2/hpack.(*Decoder).parseHeaderFieldRepr
// 未修复前 100 normal
// Showing nodes accounting for 2208.36kB, 100% of 2208.36kB total
// Showing top 10 nodes out of 19
// flat flat% sum% cum cum%
// 1184.27kB 53.63% 53.63% 1184.27kB 53.63% runtime/pprof.StartCPUProfile
// 512.08kB 23.19% 76.82% 512.08kB 23.19% golang.org/x/net/http2.init
// 512.01kB 23.18% 100% 512.01kB 23.18% golang.org/x/net/http2/hpack.addDecoderNode
// 0 0% 100% 1184.27kB 53.63% git.class100.com/backend/protobuf/benchmark_test.Test_CallUsergRPC_Normal
// 0 0% 100% 512.01kB 23.18% golang.org/x/net/http2.(*Framer).ReadFrame
// 0 0% 100% 512.01kB 23.18% golang.org/x/net/http2.(*Framer).readMetaFrame
// 0 0% 100% 512.01kB 23.18% golang.org/x/net/http2/hpack.(*Decoder).Write
// 0 0% 100% 512.01kB 23.18% golang.org/x/net/http2/hpack.(*Decoder).parseFieldLiteral
// 0 0% 100% 512.01kB 23.18% golang.org/x/net/http2/hpack.(*Decoder).parseHeaderFieldRepr
// 0 0% 100% 512.01kB 23.18% golang.org/x/net/http2/hpack.(*Decoder).readString
// 修复后，100个NotFound错误
// Showing nodes accounting for 1537.02kB, 100% of 1537.02kB total
// Showing top 10 nodes out of 14
// flat flat% sum% cum cum%
// 1024.02kB 66.62% 66.62% 1537.02kB 100% golang.org/x/net/http2/hpack.addDecoderNode
// 513kB 33.38% 100% 513kB 33.38% golang.org/x/net/http2/hpack.newInternalNode
// 0 0% 100% 1537.02kB 100% golang.org/x/net/http2.(*Framer).ReadFrame
// 0 0% 100% 1537.02kB 100% golang.org/x/net/http2.(*Framer).readMetaFrame
// 0 0% 100% 1537.02kB 100% golang.org/x/net/http2/hpack.(*Decoder).Write
// 0 0% 100% 1537.02kB 100% golang.org/x/net/http2/hpack.(*Decoder).parseFieldLiteral
// 0 0% 100% 1537.02kB 100% golang.org/x/net/http2/hpack.(*Decoder).parseHeaderFieldRepr
// 0 0% 100% 1537.02kB 100% golang.org/x/net/http2/hpack.(*Decoder).readString
// 0 0% 100% 1537.02kB 100% golang.org/x/net/http2/hpack.buildRootHuffmanNode
// 0 0% 100% 1537.02kB 100% golang.org/x/net/http2/hpack.getRootHuffmanNode
只是100个错误的触发就能看见内存占用有明显的上升，修复版本的内存占用也显著下降了。重新部署服务后，通过检查pprof，如下图：goroutine数量也正常(4000+ => 68)了。
从内存占用上看，也一直处于正常的范围（当然还需要长期观察）：
代码分析总结
该问题一直存在该服务中，甚至影响到了其上游服务，但是由于种种原因：
1. 迭代较快，服务更新频繁
2. lastGrpcReqError触发并不频繁
3. 内存超限设置较高，没有触发报警
4. 业务驱动。。。ORZ
一直得过且过，没有影响业务也就无所谓了，想起来一句话，“我们这体量，不要过早优化浪费时间，先把需求实现咯”。不过我觉的排查这种问题还是很有趣的，至少比写业务有趣。
总结
- 😂pprof我用得也不够熟练，这里姑且算是一次实践了
- 😂保留更多的罪证，方便水一篇文章，避免“口说无凭”（那我也想不到，我会写这种文章啊）
- 😂监控是个好东西，一定要监控好你的服务，并及时告警
- 😂pprof 也是个好东西，早点埋进你的服务里，避免到了要分析的时候却没有数据可用于分析
- 😂7个月太长了，以至于我都不想承认这是我写的
- 😂这里没有去分析gRPC的实现细节，因为我还没有开始看。。。先留个坑吧