gogo/protobuf 的一个性能 bug

源码阅读笔记是不可能续写的,这辈子都不可能续写的,paper notes 也是几年也不会更新一篇的,还不如把博客随便当个笔记本记录点遇到过的有意思的问题好了。

Protobuf 是 Google 整的一个序列化/反序列化框架,性能不算很好不过用的人比较多,各个语言的实现也比较全,其中 golang 的版本是 google 官方维护的 golang/protobuf,但由于比较保守,对各种新 feature request 不太感兴趣,所以社区广泛使用的是一个 fork 的版本 gogo/protobuf,gogo 版本不仅在性能上做了很多优化,而且提供了很多 extensions,可以让生成的代码更符合 go 开发的习惯。

这篇 blog 记录的是在使用 stdtime extension 中遇到的一个性能问题排查过程和修复方案。stdtime extension 可以把 Google 提供的一个公共库中 Timestamp 的类型定义转化为 golang 标准库 time.Time 的定义。

线上开发某个服务的时候用了 gRPC 和 gogo/protobuf,然后其中的 message 定义大概是:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
import "github.com/gogo/protobuf/gogoproto/gogo.proto";
import "google/protobuf/timestamp.proto";

message A {
// ...
google.protobuf.Timestamp created_at = 1 [(gogoproto.stdtime) = true];
}

message B {
repeated A as = 1;
}

message Empty {}

service S {
rpc RPC (Empty) returns (B) {}
}

大概有几千个服务会调这个 RPC,每次返回的 as 的长度大约是 10000 左右。在测试时,从客户端观察,几乎每个请求都要耗时 20 秒以上,但在服务端观察到每个请求的处理时间在 100ms 以下。在排除了网络故障的可能性以后,我开始怀疑是 RPC Framework 的问题。

Golang 自带的 profile 框架 pprof 是非常好用的,简单跑了个 mutex profile 以后,观察到

image.png

发现阻塞时间基本在 proto 包里的一个 Mutex 上。

简单翻了一下代码

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
var (
marshalInfoMap = map[reflect.Type]*marshalInfo{}
marshalInfoLock sync.Mutex
)

// getMarshalInfo returns the information to marshal a given type of message.
// The info it returns may not necessarily initialized.
// t is the type of the message (NOT the pointer to it).
func getMarshalInfo(t reflect.Type) *marshalInfo {
marshalInfoLock.Lock()
u, ok := marshalInfoMap[t]
if !ok {
u = &marshalInfo{typ: t}
marshalInfoMap[t] = u
}
marshalInfoLock.Unlock()
return u
}

看起来是为了让每个 Message Type 都只会产生一个 *marshalInfo,用了一个全局的 map 和一个全局的 Mutex 来保护。产生大量 message 的时候,这个 Mutex 成为了瓶颈。这段代码在 gogo/protobuf 和 golang/protobuf 同时存在。

当时觉得已经定位到了问题,并且修复方案也很简单,用 RWMutex 做个 double check 就好了,测试过优化明显后,顺手给 golang/protobuf 交了一个 PR

很不幸的是 golang/protobuf 的 maintainer argue 这个函数只会被调用少数次,有几个 message 定义就回被调用几次,与运行时产生的 message 数量无关。并且给出了复现例子,于是只好继续深入定位问题。

在 demo 中做了若干次详细的试验以后,发现这个 bug 确实只能用 gogo/protobuf 复现,并且必须打开 [(gogoproto.stdtime) = true] 的选项才会产生。

在打开这个特性开关后,gogo/protobuf 需要引用 google Timestamp 的定义来反序列化数据,再转化为 time.TimeTimestamp 的定义是由 protoc-gen-gogo 生成的,包路径为 github.com/gogo/protobuf/types,然而所有生成的代码都需要反过来依赖 github.com/gogo/protobuf/proto,所以会形成循环依赖。为了解决这个问题,gogo/protobuf 在 github.com/gogo/protobuf/proto 包里 mock 了一个 timestamp,只通过 struct tag 定义了最基本的序列化格式,而缺失了一些关键的方法,导致没有满足 newMarshalerMarshaler 的 interface,同时 protobuf 为了满足向后兼容性,入口函数 Marshal 依然接受不满足 newMarshalerMarshaler 的参数,只是走了最慢的路径。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
func Marshal(pb Message) ([]byte, error) {
if m, ok := pb.(newMarshaler); ok {
siz := m.XXX_Size()
b := make([]byte, 0, siz)
return m.XXX_Marshal(b, false)
}
if m, ok := pb.(Marshaler); ok {
// If the message can marshal itself, let it do it, for compatibility.
// NOTE: This is not efficient.
return m.Marshal()
}
// in case somehow we didn't generate the wrapper
if pb == nil {
return nil, ErrNil
}
var info InternalMessageInfo
siz := info.Size(pb)
b := make([]byte, 0, siz)
return info.Marshal(b, pb, false)
}

由于同时涉及了代码生成和循环依赖问题,这个问题的正确修复方式可能需要涉及到很大的重构,比较简单的 Workaround 有:

  • 使用 RWMutex 来优化这个全局 map,目前我 fork 的版本就是这么干的。
  • github.com/gogo/protobuf/proto 中依赖 github.com/golang/protobuf/ptypes 中的 Timestamp 来避免循环依赖,但会导致 gogo/protobuf 依赖 golang/protobuf,仍然不是好的解决方案。
  • 从生成的 github.com/gogo/protobuf/types.Timestamp 中 copy 更多代码到 mock 的 github.com/gogo/protobuf/proto.timestamp

目前提了一个 issue,不过 gogo/protobuf 的维护也不太活跃,在这个 issue 解决之前,建议不使用可能会触发该 bug 的 stdtime,stdduration,customtype 等 extension。