记一次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内的延迟变得不可控。平时压力小时调度上可能看不出什么来,然而尤其在压力大的时候,就表现得越差。

golang