记一次golang程序性能调优
写在前面
这是6.824 lab3A的历史遗留问题。
在3A中，要通过如下的速度测试（图中的时间是建议的运行时间）：
我的实现并不能稳定地通过这一测试：
大多数情况下，代码严重超时。要经过数百秒才能执行完成。有时甚至会在运行了较长一段时间后，报“goroutine数量超过限制”这个错误。
在这篇博客中，我试图解决这一问题。
在经过修改后，代码能够稳定地以22s左右的速度通过测试。
问题分析
这个测试的代码如下。可以发现，测试代码运行1000次Append操作，再执行一次Get，用来检验结果。
// Check that ops are committed fast enough, better than 1 per heartbeat interval
func GenericTestSpeed(t *testing.T, part string, maxraftstate int) {
const nservers = 3
const numOps = 1000
cfg := make_config(t, nservers, false, maxraftstate)
defer cfg.cleanup()
ck := cfg.makeClient(cfg.All())
cfg.begin(fmt.Sprintf("Test: ops complete fast enough (%s)", part))
// wait until first op completes, so we know a leader is elected
// and KV servers are ready to process client requests
ck.Get("x")
start := time.Now()
for i := 0; i < numOps; i++ {
ck.Append("x", "x 0 "+strconv.Itoa(i)+" y")
}
dur := time.Since(start)
v := ck.Get("x")
checkClntAppends(t, 0, v, numOps)
// heartbeat interval should be ~ 100 ms; require at least 3 ops per
const heartbeatInterval = 100 * time.Millisecond
const opsPerInterval = 3
const timePerOp = heartbeatInterval / opsPerInterval
if dur > numOps*timePerOp {
t.Fatalf("Operations completed too slowly %v/op > %v/op\n", dur/numOps, timePerOp)
}
cfg.end()
}
试图定位问题
我首先采用的方法是：通过大量的打印输出，跟踪程序的运行状态。多次跟踪运行状态后，有如下两点明显的观察：
- 代码可以快速地执行前500左右次Append。在执行第500到1000次Append时，可以明显看到代码越来越慢。
- 代码在执行前几百次Append时，代码执行的状态很正常（没有任何server故障，没有任何奇怪的事情，代码枯燥单调地向下执行。）。在执行第500到1000次Append时，偶尔会有一台server短时间不再响应，甚至偶尔出现raft新leader选举。
- 在执行第500到1000次Append时，代码会明显地在监听ApplyChannel时卡顿。当有一台server短时间不再响应时，这台server也会卡在监听ApplyCh语句这里。
- 没有发现明显的执行错误。
到这里，我们看到：代码逻辑应该是正确的，但是似乎有什么东西拖慢了代码的执行速度。猜想很可能是goroutine泄漏。可能有些带着锁的goroutine不能及时被释放，导致了上面的问题。而且，server卡在监听ApplyCh语句，似乎代表出问题的是Lab2中的Raft实现，而不是Lab3。
接下来，我去掉打印输出，调整上文中GenericTestSpeed函数中的numOps，测试不同数量Append对应的执行速度，结果如下。可以看到前500次的结果是比较正常的。
| 100 | 300 | 500 | 600 |
|---|---|---|---|
| 3s | 7.5s | 13s | 70s/100s+ |
numOps==600时的结果很有意思。首先，结果很不稳定。最好的一次用时70s完成。其它时候需要几百秒。
似乎拖慢性能的因素是在500-600之间突然出现的。而且它的影响看起来极不稳定。
接下来，我添加上打印输出，看看500到600之间发生了什么。令人惊讶的是，添加打印输出后，代码能够在18s左右完成（numOps==600）！
这个结果就很耐人寻味了：不加打印输出要跑几百秒的代码，加了打印输出之后就能在20s之内完成了？！难道是golang的Printf有什么副作用（之前好像听说有barrier之类的作用？），避免了性能下降？？查找google，也没有查到什么副作用。😭
其实在调试到这里的时候我是崩溃的。尤其是添加打印输出可以改善性能这件怪事，让人十分的疑惑不解。但是调试到后面发现问题原因的时候，其实这个现象是可以解释的。
进一步试图定位问题
上文中提到，我猜测出问题的可能是某些goroutine。于是我通过runtime.NumGoroutine()函数跟踪了一下goroutine的数量。发现goroutine在前500左右一直维持在30个左右。之后开始不稳定地增长，甚至增加至300-400个。有时也会再度回落至几十个。看起来就是goroutine这里出现了问题！
虽然goroutine可以开几千个几万个（每个只占用约4K内存），但是不正常数量的goroutine可以表示代码出现了问题。通过查看goroutine的详细信息，我们应该可以看出是哪里出了问题。
关于查看goroutine的详细信息，有文章提到pprof。尝试了一下发现不是很合适。查找了一下，发现最合适，也是最简单的方法，就是直接panic，并设置环境变量GOTRACEBACK=1（把go test --run 3A --race换成GOTRACEBACK=1 go test --run 3A --race就可以了）。我设置在goroutine个数超过100时panic。
结果如下：panic时，大约执行了600个Append，有104个goroutine。去掉每个server一个ticker、一个applier、一个applylistener（一共9个），剩余不到100个。其中有29个执行到raft_leader.go line29，也就是leader正在试图向follower发送AppendEntries RPC。还有27个RPC相关的线程，与RPC的具体实现有关，不重要。还有27个线程执行到raft.go line385，也就是follower刚刚开始处理AppendEntries RPC，并且在等待获取锁。
到这里基本上就破案了。leader发了太多的AppendEntries RPC，导致follower来不及处理。处理每个AppendEntries RPC又要获取锁，并占用锁一段时间。这就导致只要follower一旦来不及释放锁，就很可能导致AppendEntries RPC大量积压，系统雪崩，严重降速。
这也能够解释上面所说的“添加打印输出可以改善性能”这件事情。打印输出相当于减缓了发送AppendEntries RPC的速度，缓解了系统压力。
解决方案
到这里问题已经定位，解决方案就很简单了。原先raft_leader.go line153处设置每隔五分之一的heartbeatinterval(1/5*100=20ms)，leader就会重发AppendEntriesRPC来确保发送成功。这个间隔太短了。follower可能来不及在20ms内处理好AppendEntriesRPC。我将重发时间修改为一个heartbeatinterval。经过实验，这样做效果仍然不够好。于是我把heartbeatInterval调大至200ms，同时增加electionTimeoutStart至600ms。这彻底解决了问题。Ops complete fast enough test的时间稳定在22s左右，可以通过测试。同时这个修改没有影响Lab2的测试。
总结
这是我第一次做性能相关的调优。之前都是关注代码逻辑，从来没有想过代码中某些超参会对系统有如此之大的影响。虽然我所使用的工具都很简单（肉眼+肉脑），但是确确实实获得了宝贵的经验。定位问题需要强大的分析思考能力。解决问题相对简单。在此记录下这次的整个过程，方便日后再次遇到类似问题时查阅。
