工欲效能調優，必先利其器（1）

這是一個建立於 的文章，其中的資訊可能已經有所發展或是發生改變。

最近在排查 TiDB 效能問題的時候，通過工具發現了一些問題，覺得有必要記錄一下，讓自己繼續深刻的去理解相關工具的使用，也同時讓同學們對類似問題的時候別再踩坑。

使用 iostat 定位磁碟問題

在一個效能測試叢集，我們選擇了 AWS c3.4xlarge 機型，主要是為了在一台機器的兩塊盤上面分別跑 TiKV。在測試一段時間之後，我們發現有一台 TiKV 響應很慢，但是 RocksDB 並沒有相關的 Stall 日誌，而且慢查詢也沒有。

於是我登上 AWS 機器，使用 iostat -d -x -m 5 命令查看，得到如下輸出：

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %utilxvda              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00xvdb              8.00 12898.00  543.00  579.00    31.66    70.15   185.84    51.93   54.39    7.03   98.79   0.60  66.80xvdc              0.00     0.00  206.00 1190.00    10.58   148.62   233.56   106.67   70.90   13.83   80.78   0.56  78.40

上面發現，兩個盤 xvdb 和 xvdc 在 wrqm/s 上面差距太大，當然後面一些指標也有明顯的差距，這裡就不在詳細的解釋 iostat 的輸出。只是需要注意，大家通常將目光注意到 util 上面，但有時候光有 util 是反應不了問題的。

於是我繼續用 fio 進行測試，fio -ioengine=libaio -bs=4k -direct=1 -thread -rw=write -size=10G -filename=test -name="PingCAP max throughput" -iodepth=4 -runtime=60，發現兩個盤的寫入有 2 倍的差距，xvdb 的寫入竟然只有不到 70 MB，而 xvdc 有 150 MB，所以自然兩個 TiKV 一個快，一個慢了。

對於磁碟來說，通常我們使用的就是 iostat 來進行排查，另外也可以考慮使用 pidstat，iotop 等工具。

使用 perf 定位效能問題

RC3 最重要的一個功能就是引入 gRPC，但這個對於 rust 來說難度太大。最開始，我們使用的是 rust-grpc 庫，但這個庫並沒有經過生產環境的驗證，我們還是膽大的引入了，只是事後證明，這個冒險的決定還是傻逼了，一些試用的使用者跟我們反映 TiKV 時不時 coredump，所以我們立刻決定直接封裝 c gRPC。因為現在大部分語言 gRPC 實現都是基於 c gRPC 的，所以我們完全不用擔心這個庫的穩定性。

在第一個版本的實現中，我們發現，rust 封裝的 c gRPC 比 C Plus Plus 的版本差了幾倍的效能，於是我用 perf stat 來分別跑 C Plus Plus 和 rust 的benchmark，得到類似如下的輸出：

Performance counter stats for 'python2.7 tools/run_tests/run_performance_tests.py -r generic_async_streaming_ping_pong -l c++':     216989.551636 task-clock (msec)         #    2.004 CPUs utilized         3,659,896 context-switches          #    0.017 M/sec             5,078 cpu-migrations            #    0.023 K/sec         4,104,965 page-faults               #    0.019 M/sec   729,530,805,665 cycles                    #    3.362 GHz   <not supported> stalled-cycles-frontend   <not supported> stalled-cycles-backend   557,766,492,733 instructions              #    0.76  insns per cycle   121,205,705,283 branches                  #  558.579 M/sec     3,095,509,087 branch-misses             #    2.55% of all branches     108.267282719 seconds time elapsed

上面是 C Plus Plus 的結果，然後在 rust 測試的時候，我們發現 context-switch 是 C Plus Plus 的 10 倍，也就是我們進行了太多次的線程切換。剛好我們第一個版本的實現是用 rust futures 的 park 和 unpark task 機制，不停的在 gRPC 自己的 Event Loop 線程和邏輯線程之前切換，但 C Plus Plus 則是直接在一個 Event Loop 線程處理的。於是我們立刻改成類似 C Plus Plus 架構，沒有了 task 的開銷，然後效能一下子跟 C Plus Plus 的不相伯仲了。

當然，perf 能做到的還遠遠不僅於此，我們通常會使用火焰圖工具，關於火焰圖，網上已經有太多的介紹，我們也通過它來發現了很多效能問題，這個後面可以專門來說一下。

使用 strace 動態追蹤

因為我們有一個記錄線程 CPU 的統計，通常在 Grafana 展示的時候都是按照線程名字來 group 的，並沒有按照線程 ID。但我們也可以強制發送 SIGUSR1 訊號給 TiKV 在 log 裡面 dump 相關的統計資訊。在測試 TiKV 的時候，我發現 pd worker 這個 thread 出現了很多不同線程 ID 的 label，也就是說，這個線程在不停的建立和刪除。

要動態追蹤到這個情況，使用 strace -f 是一個不錯的方式，我同時觀察 TiKV 自己的輸出 log，發現當 TiKV 在處理分裂邏輯，給 PD worker 發送 message 的時候，就有一個新的線程建立出來。然後在尋找對應的代碼，發現我們每次在發訊息的時候都建立了一個 tokio-timer，而這個每次都會新建立一個線程。

有時候，也可以使用 strace -c 來動態追蹤一段時間的系統調用。在第一版本的 rust gRPC 中，我們為瞭解決 future task 導致的頻繁線程切換，使用 gRPC 自己的 alarm 來喚醒 Event Loop，但發現這種實現會產生大量的訊號調用，因為 gRPC 的 alarm 會發送一個即時訊號用來喚醒 epoll，後面通過火焰圖也發現了 Event Loop 很多 CPU 限定在 alarm 這邊，所以也在開始改進。

這裡需要注意，strace 對效能影響比較大，但對於內部效能測試影響還不大，不到萬不得已，不建議長時間用於生產環境。

小結

上面僅僅是三個最近用工具發現的問題，當然還遠遠不止於此，後續也會慢慢補上。其實對於效能調優來說，工具只是一個協助工具輔助，最重要的是要有一顆對問題敏銳的心，不然即使工具發現了問題，因為不敏銳直接就忽略了。我之前就是不敏銳栽過太多的坑，所以現在為了刻意提升自己這塊的能力，直接給自己下了死規定，就是懷疑一切能能懷疑的東西，認為所有東西都是有問題的。即使真的是正常的，也需要找到充足的理由去驗證。