谁偷了1/3个CPU - 诡异Go性能问题追根问底

看到过不少文章介绍自己CPU占用恶高甚至接近100%，其实那到反而清楚无遗漏了，无非哪个busy loop卡住了。这里为大家描述一个近期遇到的Go程序在空闲时候依旧在top命令里总报告30%左右CPU占用的问题，这样的性能问题更隐蔽更难琢磨。

问题发生在我自己做的高性能多组Raft库Dragonboat里，这是一个Apache2开源的Go实现的多组Raft库，它的主打就是吞吐性能吊打竟品几十倍。因为性能是核心卖点，因此每个函数的CPU耗费都了如指掌，直到有一天突然发现系统空载的时候占用一个CPU核的30%的负载，如下图：

服务器程序空闲的时候，top中看到的cpu负载通常应该是个位数低位。深入分析以后发现是一个较深的Go调度实现的问题。

观察

看到上述top的结果，strace -c 看了一下，很多futex。多启动几个这样的空闲进程，抓个火焰图看，它是这样的：

必须得假设您对Go近期版本(如1.8-1.11)的调度有一定基本了解，了解M、P、G三者的意义和作用。如暂时不了解，可参考本文或者该文的中文翻译。

火焰图中可以观察到几点：

• 让当前M去sleep的操作挺重的，它由tickWorkerMain试图去读一个channel引发
• runtime.futex的数据和上面提到的strace所报告的情况吻合

查看代码，Dragonboat库tickWorkerMain中有一个1khz的ticker，等于每秒读ticker.C这个channel 1000次。当时第一感觉是有些疑惑，因为常识告诉我，一个简单的非严格1khz的低频ticker，在3Ghz左右的服务器处理器上，cpu占用应该在1-2%这样极低的占用才合理。只是希望程序某个函数被一秒调用1000次，怎么就占用掉近30%的cpu？

先不管成因，孤立出这个问题点来看看。为了实现“程序某个函数被一秒调用1000次”这点，在Go中用ticker可以这么做：

package main

import (
    "time"
)

func main() {
    ticker := time.NewTicker(time.Millisecond)
    defer ticker.Stop()
    for range ticker.C {
    }
}

结果上述程序top报告25%的%CPU值。是Go的ticker实现的问题吗？换sleep循环看看：

package main

import (
    "time"
)

func main() {
    for {
        time.Sleep(time.Millisecond)
    }
}

运行上述time.Sleep程序，top报告15%的%CPU。这和同样一个sleep循环的C++在1%的%CPU有天壤之别。于是开始倾向于是Go的调度器的锅。

分析

再回到上述火焰图，park_m()后一连串操作很显眼。我们已经知道M表示Machine，通常认为是一个OS Thread，park_m()后续stopm()顾名思义就是这个把当前M给停用掉，告诉系统这个M暂时不用。

一切似乎开始明朗了。每次tickWorkerMain开始等下一个tick的时候，也就是去读ticker.C这个channel的时候都因为时间没到channel为空，当前goroutine会被park掉，这个操作很轻，只需要更改一个标志。而此时因为系统空闲，并没有别的goroutine可供调度，Go的scheduler就必须让这个M去sleep，而这个操作是较重的且有锁，最终futex的syscall被调用。更具体的，这还和Go的后台timer实现、system monitor实现有关（注意火焰图中runtime.sysmon），这里不展开。人人都会告诉你协程调度是很轻的操作，这当然没错。但他们都没有告诉你更重要的一点：协程调度反复高频出现没有goroutine可供调度的代价在Go的当前实现里是显著的。

必须指出，本问题是因为系统空闲没有goroutine可以调度造成的。显然的，系统繁忙的时候，即CPU资源真正体现价值时，上述30%的%CPU的overhead并不存在，因为大概率下会有goroutine可供调度，无需去做让M去sleep这个很重的操作。

而这一问题的影响是具体客观的：

• 用户会反复提问为何系统空闲时占30%的%CPU，空闲时进程在top里始终排顶部不是个好事
• 在一个慢速的用电池的ARM核上有这东西就麻烦了

cgo解决

我们也已经知道，C/C++做同样的事代价很轻。如果从不改业务逻辑出发，首先想到的就是不让M去sleep，不发生无goroutine可调度的情况。比如，可以用一个OS线程通过cgo独立于scheduler地去产生这个1kHz的tick，每秒从C代码去调用1000次所需的Go函数。这个思路很容易实现，无非是从Go代码里调用一个C函数，这个C函数每秒1000次的从sleep中醒来去调用Go里的1khz的tick的处理函数，具体就不贴具体代码了。

用这个思路修改了Dragonboat的代码一跑，空闲时的cpu负载大幅降低：

 

结果

上述workaround已经让这一问题对自己软件的影响极大降低了。去golang-nuts吐槽一下，再报golang的issue tracker，根本的问题还是Go Scheduler的实现。用户用1kHz的ticker不应该是这样大费周章，标准库、runtime上直接提供更高效的实现才是真正解决方案。

 

在Dragonboat的开发中，这样的performance regression几乎每周都发生。从一秒十万次吞吐到一秒一千万吞吐的进化，是算法协议不断理解的深入，也是对Go runtime习性的不断熟悉的一个过程。后面陆续会风向大量这样的性能优化实践知识，均以目前互联网后台最热门Golang为语言，素材均为任何应用均会涉及的通用场景。作为最好的教材，欢迎大家试用Dragonboat，也请大家点Star支持它的持续开发。