January 17, 2020

一次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

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

总结

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