工欲性能調優，必先利其器（2）- 火焰圖

轉自：http://www.jianshu.com/p/3cdc0f05ac5d

 

在前一篇文章，我們簡單提到了 perf，實際 perf 能做的事情遠遠不止這么少，這里就要好好介紹一下，我們在 TiKV 性能調優上面用的最多的工具 - 火焰圖。

火焰圖，也就是 FlameGraph，是超級大牛 Brendan Gregg 搗鼓出來的東西，主要就是將 profile 工具生成的數據進行可視化處理，方便開發人員查看。我第一次知道火焰圖，應該是來自 OpenResty 的章亦春介紹，大家可以詳細去看看這篇文章動態追蹤技術漫談。

之前，我的所有工作在很長一段時間幾乎都是基於 Go 的，而 Go 原生提供了很多相關的 profile 工具，以及可視化方法，所以我沒怎么用過火焰圖。但開始用 Rust 開發 TiKV 之后，我就立刻傻眼了，Rust 可沒有官方的工具來做這些事情，怎么搞？自然，我們就開始使用火焰圖了。

使用火焰圖非常的簡單，我們僅僅需要將代碼 clone 下來就可以了，我通常喜歡將相關腳本扔到 /opt/FlameGraph 下面，后面也會用這個目錄舉例說明。

一個簡單安裝的例子：

wget https://github.com/brendangregg/FlameGraph/archive/master.zip
unzip master.zip
sudo mv FlameGraph-master/ /opt/FlameGraph

CPU

對於 TiKV 來說，性能問題最開始關注的就是 CPU，畢竟這個是一個非常直觀的東西。

當我們發現 TiKV CPU 壓力很大的時候，通常會對 TiKV 進行 perf，如下：

perf record -F 99 -p tikv_pid -g -- sleep 60
perf script > out.perf

上面，我們對一個 TiKV 使用 99 HZ 的頻繁采樣 60 s，然后生成對應的采樣文件。然后我們生成火焰圖：

/opt/FlameGraph/stackcollapse-perf.pl out.perf > out.folded
/opt/FlameGraph/flamegraph.pl out.folded > cpu.svg

image.png

上面就是生成的一個 TiKV 火焰圖，我們會發現 gRPC 線程主要開銷在 c gRPC core 上面，而這個也是現在 c gRPC core 大家普遍反映的一個問題，就是太費 CPU，但我相信憑借 Google gRPC team 的實力，這問題應該能夠搞定。

另外，在 gRPC 線程上面，我們可以發現，protobuf 的編解碼也占用了很多 CPU，這個也是現階段 rust protobuf 庫的一個問題，性能比較差，但幸好后面的辦法有一個優化，我們准備馬上采用。

另外，還需要注意，raftstore 線程主要的開銷在於 RocksDB 的 Get 和 Write，對於 TiKV 來說，如果 raftstore 線程出現了瓶頸，那么整個 Raft 流程都會被拖慢，所以自然這個線程就是我們的重點優化對象。

可以看到，Get 的開銷其實就是我們拿到 Raft 的 committed entries，然后扔給 apply Raft log 線程去異步 apply，所以自然這一步 Get 自然能扔到 apply worker 去處理。另外，對於 Write，鑒於 Raft log 的格式，我們可以非常方便的使用 RocksDB 一個 insert_with_hint 特性來優化，或者將 Write 也放到另一個線程去 async 處理。

可以看到，我們通過火焰圖，能夠非常方便的發現 CPU 大部分時間開銷都消耗在哪里，也就知道如何優化了。

這里在說一下，大家通常喜歡將目光定在 CPU 消耗大頭的地方，但有時候一些小的不起眼的地方，也需要引起大家的注意。這里並不是這些小地方會占用多少 CPU，而是要問為啥會在火焰圖里面出現，因為按照正常邏輯是不可能的。我們通過觀察 CPU 火焰圖這些不起眼的小地方，至少發現了幾處代碼 bug。

Memory

通常大家用的最多的是 CPU 火焰圖，畢竟這個最直觀，但火焰圖可不僅僅只有 CPU 的。我們還需要關注除了 CPU 之外的其他指標。有一段時間，我對 TiKV 的內存持續上漲問題一直很頭疼，雖然 TiKV 有 OOM，但總沒有很好的辦法來定位到底是哪里出了問題。於是也就研究了一下 memory 火焰圖。

要 profile TiKV 的 memory 火焰圖，其實我們就需要監控 TiKV 的 malloc 分配，只要有 malloc，就表明這時候 TiKV 在進行內存分配。因為 TiKV 是自己內部使用了 jemalloc，並沒有用系統的 malloc，所以我們不能直接用 perf 來探查系統的 malloc 函數。幸運的是，perf 能支持動態添加探針，我們將 TiKV 的 malloc 加入：

perf probe -x /deploy/bin/tikv-server -a malloc

然后采樣生成火焰圖:

perf record -e probe_tikv:malloc -F 99 -p tikv_pid -g -- sleep 10
perf script > out.perf
/opt/FlameGraph/stackcollapse-perf.pl out.perf > out.folded
/opt/FlameGraph/flamegraph.pl  --colors=mem out.folded > mem.svg

image.png

上面是生成的一個 malloc 火焰圖，我們可以看到，大部分的內存開銷仍然是在 RocksDB 上面。

通過 malloc 火焰圖，我們曾發現過 RocksDB 的 ReadOption 在非常頻繁的調用分配，后面准備考慮直接在 stack 上面分配，不過這個其實對性能到沒啥太大影響 :sweat: 。

除了 malloc，我們也可以 probe minor page fault 和 major page fault，因為用 pidstat 觀察發現 TiKV 很少有 major page fault，所以我們只 probe 了 minor，如下：

perf record -e minor-faults -F 99 -p $1 -g -- sleep 10
perf script > out.perf
/opt/FlameGraph/stackcollapse-perf.pl out.perf > out.folded
/opt/FlameGraph/flamegraph.pl  --colors=mem out.folded > minflt.svg

Off CPU

有時候，我們還會面臨一個問題。系統的性能上不去，但 CPU 也很閑，這種的很大可能都是在等 IO ，或者 lock 這些的了，所以我們需要看到底 CPU 等在什么地方。

對於 perf 來說，我們可以使用如下方式采樣 off CPU。

perf record -e sched:sched_stat_sleep -e sched:sched_switch \
    -e sched:sched_process_exit -p tikv_pid -g -o perf.data.raw sleep 10
perf inject -v -s -i perf.data.raw -o perf.data

但不幸的是，上面的代碼在 Ubuntu 或者 CentOS 上面通常都會失敗，主要是現在最新的系統為了性能考慮，並沒有支持 sched statistics。 對於 Ubuntu，貌似只能重新編譯內核，而對於 CentOS，只需要安裝 kernel debuginfo，然后在打開 sched statistics 就可以了，如下:

dnf install kernel-debug kernel-debug-devel kernel-debug-debuginfo
echo 1 | sudo tee /proc/sys/kernel/sched_schedstats

然后生成 off cpu 火焰圖:

perf script -F comm,pid,tid,cpu,time,period,event,ip,sym,dso,trace | awk '
    NF > 4 { exec = $1; period_ms = int($5 / 1000000) }
    NF > 1 && NF <= 4 && period_ms > 0 { print $2 }
    NF < 2 && period_ms > 0 { printf "%s\n%d\n\n", exec, period_ms }' | \
    /opt/FlameGraph/stackcollapse.pl | \
    /opt/FlameGraph/flamegraph.pl --countname=ms --title="Off-CPU Time Flame Graph" --colors=io > offcpu.svg

image.png

上面就是 TiKV 一次 off CPU 的火焰圖，可以發現只要是 server event loop 和 time monitor 兩個線程 off CPU 比較長，server event loop 是等待外部的網絡請求，因為我在 perf 的時候並沒有進行壓力測試，所以 wait 是正常的。而 time monitor 則是 sleep 一段時間，然后檢查時間是不是出現了 jump back，因為有長時間的 sleep，所以也是正常的。

上面我說到，對於 Ubuntu 用戶，貌似只能重新編譯內核，打開 sched statistics，如果不想折騰，我們可以通過 systemtap 來搞定。systemtap 是另外一種 profile 工具，其實應該算另一門語言了。

我們可以直接使用 OpenResty 的 systemtap 工具，來生成 off CPU 火焰圖，如下：

wget https://raw.githubusercontent.com/openresty/openresty-systemtap-toolkit/master/sample-bt-off-cpu
chmod +x sample-bt-off-cpu

./sample-bt-off-cpu -t 10 -p 13491 -u > out.stap
/opt/FlameGraph/stackcollapse-stap.pl out.stap > out.folded
/opt/FlameGraph/flamegraph.pl --colors=io out.folded > offcpu.svg

可以看到，使用 systemptap 的方式跟 perf 沒啥不一樣，但 systemtap 更加復雜，畢竟它可以算是一門語言。而 FlameGraph 里面也自帶了 systemaptap 相關的火焰圖生成工具。

Diff 火焰圖

除了通常的幾種火焰圖，我們其實還可以將兩個火焰圖進行 diff，生成一個 diff 火焰圖，如下：

/opt/difffolded.pl out.folded1 out.folded2 | ./flamegraph.pl > diff2.svg

image.png

但現在我僅僅只會生成，還沒有詳細對其研究過，這里就不做過多說明了。

總結

上面簡單介紹了我們在 TiKV 里面如何使用火焰圖來排查問題，現階段主要還是通過 CPU 火焰圖發現了不少問題，但我相信對於其他火焰圖的使用研究，后續還是會很有幫助的。

作者：siddontang
鏈接：http://www.jianshu.com/p/3cdc0f05ac5d
來源：簡書
著作權歸作者所有。商業轉載請聯系作者獲得授權，非商業轉載請注明出處。