golang http client 使用gzip_一次gRPC使用不当导致goroutine泄漏排查记录

由于保留必要的“罪证”，因此某些异常只能通过文字来描述了～背景昨晚上10点左右，前端童鞋反映开发环境接口响应超时，但过了几分钟后又恢复了，于是有了这一篇文章。其实很久以前就出现了内存占用异常的情况～，只是占用并不高也就是50MB左右，加上当时还忙着写业务需求就没有急着加上pprof来检查。首先通过运维平台(k8s based)直观发现了该pod数量从1变成了2, 再结合新增pod的启动时间，我.

Jason任

585人浏览 · 2020-11-29 19:55:57

Jason任 · 2020-11-29 19:55:57 发布

由于保留必要的“罪证”，因此某些异常只能通过文字来描述了～

背景

昨晚上10点左右，前端童鞋反映开发环境接口响应超时，但过了几分钟后又恢复了，于是有了这一篇文章。

其实很久以前就出现了内存占用异常的情况～，只是占用并不高也就是50MB左右，加上当时还忙着写业务需求就没有急着加上pprof来检查。

首先通过运维平台(k8s based)直观发现了该pod数量从1变成了2, 再结合新增pod的启动时间，我发现该时间正好是前端童鞋反映状况的时间节点，稍后我检查了下该服务的资源限制如下图：

k8s pod 资源限制

那么前端童鞋反映的问题就很明显了，由于某种原因导致了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/goroutines详情 - gRPC客户端相关部分（修复后）

pprof总结

服务中使用的gRPC客户端出了某些故障，导致了goroutine泄漏，引发了OOM（Out Of Memory）。如下图：

pod 内存占用详情

代码排查

上一步已经定位到是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)了。

修复后 pprof 概览

从内存占用上看，也一直处于正常的范围（当然还需要长期观察）：

修复后 pod 内存占用

代码分析总结

该问题一直存在该服务中，甚至影响到了其上游服务，但是由于种种原因：

1. 迭代较快，服务更新频繁
2. lastGrpcReqError触发并不频繁
3. 内存超限设置较高，没有触发报警
4. 业务驱动。。。ORZ

一直得过且过，没有影响业务也就无所谓了，想起来一句话，“我们这体量，不要过早优化浪费时间，先把需求实现咯”。不过我觉的排查这种问题还是很有趣的，至少比写业务有趣。

总结

pprof我用得也不够熟练，这里姑且算是一次实践了
保留更多的罪证，方便水一篇文章，避免“口说无凭”（那我也想不到，我会写这种文章啊）
监控是个好东西，一定要监控好你的服务，并及时告警
pprof 也是个好东西，早点埋进你的服务里，避免到了要分析的时候却没有数据可用于分析
7个月太长了，以至于我都不想承认这是我写的
这里没有去分析gRPC的实现细节，因为我还没有开始看。。。先留个坑吧

K8S/Kubernetes

K8S/Kubernetes社区为您提供最前沿的新闻资讯和知识内容

更多推荐

【深度】阿里巴巴万级规模 K8s 集群全局高可用体系之美

作者 | 韩堂、柘远、沉醉来源 | 阿里巴巴云原生公众号前言台湾作家林清玄在接受记者采访的时候，如此评价自己 30 多年写作生涯：“第一个十年我才华横溢，‘贼光闪现’，令周边黯然失色；第二个十年，我终于‘宝光现形’，不再去抢风头，反而与身边的美丽相得益彰；进入第三个十年，繁华落尽见真醇，我进入了‘醇光初现’的阶段，真正体味到了境界之美”。长夜有穷，真水无香。领略过了 K8s“身在江

K8S/Kubernetes

如何基于 K8s 构建下一代 DevOps 平台？

作者 | 孙健波（天元）导读：当前云原生 DevOps 体系现状如何？面临哪些挑战？如何通过 OAM 解决云原生 DevOps 场景下的诸多问题？云原生开发应用模型 OAM(Open Application Model) 社区核心成员孙健波将为大家一一解答，并分享如何基于 OAM 和 Kubernetes 打造无限能力的下一代 DevOps 平台。什么是 DevOps？为什么基于 Kub