记一次latency问题排查：谈Go的公平调度的缺陷

2017-11-19

我们有一个对延迟很敏感的模块，这个模块需要访问网络中的另一台机器去取一个时间戳。实现一次分布式事务，需要执行这个操作两次，如果这里拿时间戳慢了，整个事务的延迟就会上升。理论上内网环境同机房一次网络的round trip应该在0.5ms以内，大部分简单读请求应该落在1ms，80%请求的延迟预期也是4ms以内。有客户反鐀说这里有30ms以上的延时，在内网环境用sysbench跑OLTP测试了一下能够复现，于是查了一下这个问题。

在opentracing里面观察，这一步确实存在较大的延时，日志里面也有打印大量的慢log，影响了事务整体的完成时间。首先方向是确定慢在哪里，到底是网络有问题还是runtime有问题。

一个同事观察到，跑这个模块的benchmark时，额外开启1000个goroutine的worker，每秒钟tick空转，跟只跑benchmark对比，发现前者的延迟要比后者高出许多。怀疑runtime有问题。

另一个同事先单独跑测试，并观察网络，会发现网络重传对结果有明显影响；然后改到客户端服务器在同一机器上再测试，排除掉网络干扰，结果发现进程之间会相互影响；再将服务器和客户端分别绑到不同核之后，服务端处理时间比较稳定，而客户端仍然出现高延迟。到这一步的结论基本上是：runtime和网络都不能保证稳定。

然而runtime的影响能使达到几十ms级别么？看起来不太合理。在我印象中，怎么都应该控制在微秒数量级，即便回到Go语言1.0的版本，stop the world的GC也不见得这么挫。何况现在都优化到1.9了，GC早就不会stop the world的了。于是我使用go tool trace工具，继续分析问题。不看不知道，一看还真吓了一跳。

抓的这一段图，红线箭头是指收到网络消息，ublock了goroutine的Read操作。注意，从网络消息可读，到读网络的goroutine被再次调度，中间花费了4.368ms !!! 我甚至找到一些更极端的场景，从收到网络消息可读，到goroutine实际被唤醒，花费了19ms。这里先插入讲一下业务情况，出于性能考虑，业务实现是做了batch的，所以请求都会通过channel转发到一个goroutine上，由那个goroutine去batch的发请求。显然这个goroutine是非常关键的，因为其它的goroutine都是依赖于它。这里ms级别的调度延迟，直接会对业务整体延迟产生很大影响。

然后说下goroutine的调度时机，goroutine是协程，如果可以执行，会一直执行，直到阻塞才会放弃CPU。比如执行遇到锁了，或者读channel，或者读io请求等等。goroutine被切换出去之后，如果条件满足了，会被丢到ready队列里面去排队，等待被再次运行。然而，具体什么时候会被执行，是不确定的，跟排队的任务队列长度，排在它前面的任务要执行的时间，以及当时的负载情况等等很多因素有关。

这里的问题不是GC，而是调度。最终的延迟问题是跟Go的调度设计相关的，主要是协程的公平调度策略：

• 不可以抢占
• 没有优先级的概念

由于不可以抢占，假设网络消息好了，但这个时刻所有的CPU上面都正好有goroutine在跑着，并不能将谁踢掉，于是读网络的那个goroutine并没机会被唤醒。

由于没有优先级的概念，假设终于有goroutine阻塞并让出CPU了，这时让谁执行完全是看调度器的心情，读网络的那个goroutine运气不好，又没被唤醒。

只要goroutine不走到函数调用，是没有机会触发调度，不会让出CPU的。

Go声称可以开千千万万个goroutine，其实是有开销的：越多的goroutine被“公平”调度，越可能影响其中重要goroutine的唤醒，进而影响整体延迟。

回头再想之前同事那个测试，空跑worker会影响延时，也就能解释通了：由于被调度概率均等，越多无关的goroutine，则干活的那个goroutine被调度的概率越低，于是导致延迟增加。

Go的垃圾回收虽然不stop the world，仍然可能影响延迟：GC是可以打断goroutine，要求让出CPU的，而什么时候goroutine被再次调回来又看脸。

有太多太多的因素来影响调度，使整个runtime内的延迟变得不可控。平时压力小时调度上可能看不出什么来，然而尤其在压力大的时候，就表现得越差。