作者：王璐璐 | 曠視 MegEngine 架構師
一、 背景
在 MegEngine imperative runtime 的早期開發中，我們面臨著一些的效能優化問題。除了一些已知需要重構的地方（早期設計時為了開發效率而犧牲效能的妥協），還存在一些未知的效能問題需要用 profiler 進行觀測和分析才能發現。MegEngine 的 imperative runtime 是一個由 Python 和 C/C++ 編寫的模組，對於這類程式，各種 profiler 多到令人眼花繚亂。在調研各種 profiler 的過程中，我們也踩了不少的坑，比如發現兩個 profiler 對同一個程式的 profiling 結果差異巨大，我們起初懷疑其中一個 profiler 的準確性有問題，最後發現是兩者的觀測物件不同，其中一個只 profiling 程式的 CPU time，而另一個 profiling wall clock time。雖然一些這樣的資訊在文件的某些角落裡能夠找到，但很多使用者可能在踩了坑之後才會注意到。如果一開始能找到一篇介紹各種 profiler 的特點、優勢、不足和使用場景的文章，我們可能會節省不少時間。
因此本文嘗試對這些經驗進行總結，希望能夠給初次使用這些工具的讀者一些參考。效能優化是一個十分廣泛的話題，它涉及 CPU、記憶體、磁碟、網路等方面，本文主要關注 Python 及 C/C++ 擴充程式在 CPU 上的效能優化，文章主要圍繞著下面三個問題展開:
- Python 及 C/C++ 擴充程式的常見的優化目標有哪些
- 常見工具的能力範圍和侷限是什麼，給定一個優化目標我們應該如何選擇工具
- 各種工具的使用方法和結果的視覺化方法
除此之外，本文還會介紹一些效能優化中需要了解的基本概念，並在文章末尾以 MegEngine 開發過程中的一個效能優化的實際案例來展示一個優化的流程。
二、 基本概念
本節介紹效能優化中的一些基礎概念:
2.1 wall clock time, CPU time 和 off-CPU time
衡量程式效能最直接的標準就是程式的執行時間，但僅僅知道程式的執行時間很難指導我們如何把程式優化地更快，我們想要更進一步地瞭解這段時間之內到底發生了什麼。
Linux 系統上的 time 命令能夠告訴我們一些粗糙的資訊，我們在命令列裡輸出下面的命令來測量檢查某個檔案的 CRC 校驗碼的執行時間:
time cksum \<some_file\>
以我的電腦(MacBook Pro 2018)為例，得到了以下輸出:
8.22s user 1.06s system 96% cpu 9.618 total
這段文字告訴了我們時間都花在了哪裡:
- 總時間 9.618s
- user時間 8.22s
- system時間 1.06s
其中 user 和 system 的含義是 user CPU time 和 system CPU time, 之所以會把 CPU 的執行時間分為兩個部分，是因為程式在執行時除了執行程式本身程式碼和一些庫的程式碼，還會呼叫作業系統提供的函式(即系統呼叫，程式執行系統呼叫時有更高的許可權)，因此程式執行時通常會處於兩種狀態: 使用者態和核心態: 核心態指的是 CPU 在執行系統呼叫時的狀態，而使用者態就是 CPU執行非系統呼叫（即使用者自己的程式碼或一些庫）時的狀態。
因此上面提到的 user CPU time 指的是使用者態所花費的時間，而 system CPU time 指的是核心態花費的時間。
我們發現 user CPU time + system CPU time = 8.22s + 1.06s = 9.28s 並不等於總時間 9.618s，這是因為這條命令執行的時間內，程式並不是總是在 CPU 上執行，還有可能處於睡眠、等待等狀態，比如等待檔案從磁碟載入到記憶體等。這段時間既不算在user CPU time也不算在 system CPU time內。我們把程式在CPU上執行的時間(即user CPU time + system CPU time)稱為 CPU time (或on-CPU time), 程式處於睡眠等狀態的時間稱為off-CPU time (or blocked time)，程式實際執行的時間稱為wall clock time（字面意思是牆上時鐘的時間，也就是真實世界中流逝的時間），對於一個給定的執行緒: wall clock time = CPU time + off-CPU time。
通常在計算密集型（CPU intensive）的任務中CPU time會佔據較大的比重，而在I/O密集型（I/O intensive）任務中off-CPU time會佔據較大的比重。搞清楚CPU time和off-CPU time的區別對效能優化十分重要，比如某個程式的效能瓶頸在off-CPU time上，而我們選擇了一個只觀測CPU time的工具，那麼很難找到真正的效能瓶頸，反之亦然。
2.2 效能觀測工具
我們知道了一個執行緒執行過程中的CPU time 和 off-CPU time，如果要對程式的效能進行優化，這些還遠遠不夠，我們需要進一步知道CPU time的時間段內，CPU上到底發生了哪些事情、這些事情分別消耗了多少時間、在哪裡導致了執行緒被block住了、分別block了多久等。我們需要效能觀測工具來獲得這些詳細的資訊。通常情況下我們也將稱這種觀測工具稱為profiler。
不同的觀測物件對應著不同的profiler，僅就CPU而言，profiler也數不勝數。
按照觀測範圍來分類，CPU上的profiler大致可以分為兩大類: 程式級(per-process, 某些地方也叫做應用級)和系統級(system wide)，其中:
- 程式級只觀測一個程式或執行緒上發生的事情
- 系統級不侷限在某一個程式上，觀測物件為整個系統上執行的所有程式
需要注意的是，某些工具既能觀測整個系統也支援觀測單個程式，比如 perf，因此這樣的工具同時屬於兩個類別。
按照觀測方法來分類，大致可以分為 event based 和 sampling based 兩大類。其中:
- event based: 在一個指定的 event 集合上進行，比如進入或離開某個/某些特定的函式、分配記憶體、異常的丟擲等事件。event based profiler 在一些文章中也被稱為tracing profiler 或 tracer
- sampling based: 以某一個指定的頻率對執行的程式的某些資訊進行取樣，通常情況下采樣的物件是程式的呼叫棧
即使確定了我們優化的物件屬於上述的某一個類別，仍然有更細粒度的分類。在選擇工具之前要搞清楚具體的優化物件是什麼，單個 profiler 一般無法滿足我們所有的需求，針對不同的優化物件 (比如 Python 執行緒、C/C++ 執行緒等) 我們需要使用不同的 profiler。並且，對於同一個優化物件，如果我們關注的資訊不同，也可能需要使用不同的 profiler。
2.3 Python 程式模型
本文主要關注 Python（包括C/C++擴充) 程式的優化，一個典型的 Python 和 C/C++ 擴充程式的程式如下圖所示:
一個Python程式必須包含一個Python主執行緒，可能包含若干個Python子執行緒和若干個C/C++子執行緒。因此我們進一步把優化物件細分為三類:
- Python執行緒中的Python程式碼
- Python執行緒中的C/C++擴充程式碼
- C/C++執行緒
這裡的Python執行緒具體指CPython直譯器執行緒，而C/C++執行緒指不包含Python呼叫棧的C/C++執行緒。
三、 profiler的分類和選擇
我們從以下兩個角度對profiler進行刻畫:
- 是否支援profiling time、off-CPU time和wall clock time (CPU time + off-CPU time)
- 是否支援profiling C/C++ stack
- 是否能夠從CPython直譯器的呼叫棧中解析出Python呼叫棧
我們介紹將介紹6個profiler，分別為py-spy、cProfile、pyinstrument、perf、systemtap和eu-stack。為了方便大家進行選擇，我們按照上面介紹的特徵，把這些profiler分成了4類並總結在了下面的表格中 (其中✔、⚠、×分別表示支援、不完全支援和不支援):
表格中第一種是純Python profiler，只能觀測Python執行緒中Python函式的呼叫棧，適合優化純Python程式碼時使用，本文將介紹CProfile（Python的built-in profiler）和pyinstrument（第三方Python profiler），這類profiler還有很多，比如scalene、line-profiler、pprofile等，由於這些profiler在能力上差異不大，因此這裡就不一一介紹了。
第二類是Python執行緒profiler，與第一類的主要區別是除了能夠觀測Python執行緒裡的Python呼叫棧，還能觀測c/c++擴充的呼叫棧，這一類只介紹py-spy。
第三類是系統級profiler，我們主要用來觀測Python執行緒中的C/C++擴充的呼叫棧和純C/C++執行緒，這類profiler雖然能夠觀測CPython直譯器的呼叫棧，但由於不是專為Python設計的profiler，不會去解析Python函式的呼叫棧，因此不太適合觀測Python stack。這一類工具我們將介紹perf和systemtap。
最後一類是對第三類的補充，由於第三類介紹的兩個工具都無法在wall clock time (CPU time + off-CPU time) 上觀測程式，eu-stack可以在wall clock time上取樣程式的C/C++呼叫棧，因此可以作為這種場景下的profiler。
表格中的overhead指profiler執行時對被profiling程式的影響，overhead越大profiling的結果準確度越低。需要注意的是，任何profiler都無法做到絕對的準確，profiler本身對程式帶來的影響、取樣的隨機性等都會對結果造成影響，我們不應該將profiling結果作為程式執行時的實際情況，而應該將其視為一種對實際情況的估計（這種估計甚至是有偏的）。
除了profiler，我們還需要一些工具來對profiling的結果進行視覺化來分析效能瓶頸。與profiler不同的是，視覺化工具一般具有較強通用性，一種廣泛使用的工具是火焰圖(flamegraph)，本文將介紹flamegraph的使用方法，除此之外還會介紹一個火焰圖的改進版工具: speedscope。
由於profiler的介紹裡需要引用視覺化工具，因此接下來我們先介紹視覺化工具，再介紹profiler。
四、視覺化工具
4.1 flamegraph
火焰圖（flamegraph）是一個功能強大的視覺化profiling結果的工具。它即可以對多種profiler的輸出進行處理，也可以對處理後的結果進行視覺化。它能夠處理不同平臺上的十多種profiler的原始輸出，除了能夠視覺化cpu上的profiling結果，它也可以對一些記憶體profiler的輸出結果進行視覺化。
flamegraph的使用流程一般是對profiler的原始輸出結果進行處理，之後再生成一個SVG檔案，可以在瀏覽器裡開啟，效果如下:
flamegraph的主要功能就是顯示profiler取樣的呼叫棧的頻率分佈，圖中縱向堆起來的代表呼叫棧，呼叫棧中的矩形塊的寬度代表該函式執行時被採到的頻率（某個執行路徑的時間佔比與它被取樣到的概率成正比，因此取樣頻率近似等於該執行路徑的時間佔比）。通過觀察火焰圖，我們可以看到程式都有哪些執行路徑，以及每個執行路徑的時間佔比，然後對時間佔比較大的效能瓶頸（或"熱點"）進行優化，來達到優化效能的目的。
如果想深入瞭解flamegraph，可以參考作者的主頁或github repo:
- homepage: http://www.brendangregg.com/flamegraphs.html
- github repo: https://github.com/brendangregg/FlameGraph
4.2 speedscope
另外一個值得介紹的工具是speedscope。speedscope的使用方法和flamegraph類似，且相容flamegraph的輸出格式。與flamegraph相比，speedscope在兩個方面具有優勢: 1) speedscope在視覺化效果、互動性等方面表現十分優秀，2) speedscope執行時的開銷比SVG低很多，同時開很多視窗也不會造成明顯示卡頓。因此，我們推薦把speedscope與flamegraph結合在一起使用: 用flamegraph來處理不同工具的輸出資料，用speedscope進行視覺化。speedscope是一個web app，作者提供了一個可以直接使用的地址: https://www.speedscope.app/, 我們也可以在本地部署，但更前者更方便。本文主要以speedscope來視覺化profiling結果，下面簡單介紹一下它的使用方法:
進入https://www.speedscope.app/中，開啟json格式的profiling結果 (我們會在下面各種profiler的使用方法中介紹如何將結果轉為這種json)。可以看到以下介面 (與flamegraph的一個不同之處是speedscope的呼叫棧是倒過來的):
左上角可以選擇三種模式:
- Time Order: 即時間軸模式，從左到右代表時間的方向，中間每一列代表改時刻取樣的呼叫棧
- Left Heavy: 按照呼叫棧函式的時間佔比(取樣次數佔比來估計時間佔比)進行展示，即呼叫棧的每一層都按照左側時間多右側時間短的順序來排序。點選任何一個呼叫棧中的函式:
- 可以在圖中左下角看到該函式在當前呼叫棧(This Instance)的總開銷(Total) 和自身開銷(Self)，以及該函式在所有出現過的呼叫棧(All Instances)中的總開銷(Total)和自身開銷(Self), 圖中的整數代表被取樣的次數，百分比為被取樣的佔比(近似等於時間佔比)。
- 圖下方的白色框內是該函式的呼叫棧。
- Sandwich:用函式的總開銷和自身開銷來排序，點選函式可以看到該函式的呼叫者和被呼叫者
更詳細的介紹可以參考speedscope的官方repo: https://github.com/jlfwong/speedscope
五、效能觀測工具
接下來我們介紹幾個在Python和C/C++擴充程式的優化過程中常用的profiler。我們將介紹每種profiler的優點和侷限，大家應該根據自己的實際需求來選擇合適的工具。
5.1 py-spy
py-spy是一個sampling based profiler, 它的profiling的物件是Python及C/C++ 擴充的呼叫棧。py-spy的overhead中等，對執行的程式速度影響不算太大。且本身支援直接輸出speedscope和flamegraph格式的結果。
repo: https://github.com/benfred/py-spy
可以直接使用pip進行安裝:
pip install py-spy
使用方法:
# 基本使用方法:
py-spy record --format speedscope -o output.json --native -- python3 xxx.py
# =====
# 主要引數:
# --format: 輸出格式，預設是flamegraph，推薦使用speedscope格式
# --output: 輸出檔名
# --native: 是否取樣C/C++呼叫棧，不加--native只會對Python呼叫棧進行取樣
# =====
# 其他引數
# --rate: 取樣頻率，預設值為100，開啟--native會增大overhead，建議開啟--native時調低--rate
# --subprocesses: 是否對子程式進行取樣，預設為否
# --gil: 是否只對拿到Python GIL的執行緒進行取樣
# --threads: 在輸出中顯示thread id
# --idle: 是否對idle(即off-CPU time)的thread進行取樣，預設為否，根據具體場景選擇是否開啟
# =====
# 例子:
py-spy record -sti --rate 10 --format speedscope --native -o output.json -- python3 xxx.py
# 除了在啟動時執行py-spy，還可以對一個已經執行的python程式進行取樣，如:
py-spy record --format speedscope -o output.json --native --pid 12345
其他功能:
除了record子命令外，py-spy還提供了top子命令: 可以在命令列中動態顯示時間開銷最大函式排序; 以及dump子命令: 可以列印一個正在執行的python程式的呼叫棧。具體使用方法可以參考文件: https://github.com/benfred/py-spy
py-spy支援在CPU time或wall clock time (CPU time + off-CPU time) 上對程式的呼叫棧進行取樣，取樣的物件是Python執行緒的python呼叫棧或c/c++擴充的呼叫棧。
py-spy雖然也能對C/C++執行緒的呼叫棧進行取樣，但目前（v0.3.4）會把Python呼叫棧與C/C++呼叫棧拼在一起 (詳見GitHub相關issue：https://github.com/benfred/py-spy/issues/332) ，無論兩者是否真正存在呼叫關係，這樣會使C/C++執行緒的profiling結果在視覺化時按照Python呼叫棧進行聚合，導致很難進行分析，因此py-spy目前只適合對純Python程式碼以及Python執行緒上的C/C++擴充(存在Python到C/C++的呼叫關係)進行觀測，不適合觀測獨立的C/C++執行緒，這是py-spy的一個不足之處。
5.2 cProfile
cProfile是一個event based profiler，它的工作原理是追蹤Python直譯器上的每一個Python函式呼叫和時間開銷。cProfile是Python的built-in profiler，理論上對Python的支援度相對較高。cProfile的侷限有很多：
- 只能觀測純Python的函式呼叫，無法看到C/C++ 擴充的呼叫棧
- 只支援wall clock time
- overhead相對較大
使用方法:
python3 -m cProfile xxx.py
cProfile的輸出格式是一個table, 如下:
2173 function calls (2145 primitive calls) in 10.230 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:103(release)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:143(__init__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:147(__enter__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:151(__exit__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:157(_get_module_lock)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:176(cb)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:211(_call_with_frames_removed)
32 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:222(_verbose_message)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:307(__init__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:311(__enter__)
....
也可以指定輸出檔案:
python3 -m cProfile -o xxx.cprof xxx.py
原始輸出不方便分析，我們需要一些第三方工具來處理輸出資料和視覺化，下面介紹兩種方法:
- 轉成一個call graph的圖片
# dependency: gprof2dot, graphviz
# sudo apt install graphviz
# pip3 install gprof2dot
gprof2dot -f pstats xxx.cprof | dot -Tpng -o xxx.png && feh
視覺化效果如下:
- 轉成flamegraph
# dependency: flameprof
# pip3 install flameprof
flameprof xxx.cprof > flamegraph.svg
更多資訊請參考cProfile文件: https://docs.python.org/3/library/profile.html
5.3 pyinstrument
pyinstrument是一個sampling based profiler，功能上與cProfile類似，只支援Sampling純Python呼叫棧，類似地只支援wall clock time，但overhead相對cProfile低一些，且自帶多種視覺化方法。
官方repo地址: https://github.com/joerick/pyinstrument
安裝:
pip3 install pyinstrument
使用方法:
python3 -m pyinstrument xxx.py
預設輸出結果在命令列中，如下:
_ ._ __/__ _ _ _ _ _/_ Recorded: 15:50:07 Samples: 8794
/_//_/// /_\ / //_// / //_'/ // Duration: 23.332 CPU time: 31.381
/ _/ v3.4.1
Program: train.py
23.331 <module> train.py:9
├─ 22.641 main train.py:29
│ └─ 22.631 worker train.py:114
│ ├─ 10.077 item megengine/core/tensor/array_method.py:391
│ │ └─ 10.067 numpy megengine/tensor.py:113
│ │ └─ 10.067 Tensor.numpy <built-in>:0
│ ├─ 8.056 train_step train_random.py:159
│ │ ├─ 5.396 __call__ megengine/module/module.py:120
│ │ │ └─ 5.392 forward model.py:170
│ │ │ └─ 5.348 __call__ megengine/module/module.py:120
│ │ │ └─ 5.239 forward megengine/module/sequential.py:94
│ │ │ └─ 5.198 __call__ megengine/module/module.py:120
│ │ │ └─ 4.838 forward model.py:87
...
也可以輸出html檔案在瀏覽器裡檢視上面的結果：
python3 -m pyinstrument \--html xxx.py
效果如下:
5.4 perf
perf是Linux官方的profiler，可以在Linux kernel中找到它的原始碼。perf的功能十分強大，它同時支援對整個作業系統進行觀測，也支援對單個給定的程式進行觀測，除此之外perf即可以trace指定的event也支援對程式的呼叫棧進行sampling。perf執行在核心態，其自身的overhead非常低。
安裝perf:
sudo apt-get install linux-tools-common linux-tools-generic linux-tools-\uname -r\
perf的版本需要與Linux kernel的版本保持一致，安裝命令中的 uname -r 確保了這一點
使用方法:
# 直接執行程式並進行取樣，如python3 xxx.py
perf record -F 99 --call-graph dwarf python3 xxx.py
# 或對給定執行緒id(TID)進行取樣
perf record -F 99 --call-graph dwarf --tid <TID>
# 其中-F 99是取樣頻率，這裡指每秒取樣99次; 也可以用--pid指定取樣的程式id，此時perf會對該程式的所有執行緒進行取樣
執行結束後會在當前的目錄下產生一個名為perf.data的檔案
對結果進行視覺化:
可以使用perf自帶的子命令分析profiling結果:
perf report \--stdio -i perf.data
我們更推薦將其轉為火焰圖:
# 將perf.data轉成呼叫棧
perf script -i perf.data > perf.unfold
# clone FlameGraph
git clone https://github.com/brendangregg/FlameGraph
cd FlameGraph
# 假設perf.unfold放在了<result_dir>裡
stackcollapse-perf.pl <result_dir>/perf.unfold > perf.fold
# 可以直接在speedscope裡開啟perf.fold，或者將其轉化為svg:
# 將perf.fold轉為svg檔案
flamegraph.pl perf.fold > perf.svg
對Linux kernel版本大於等於5.8的使用者，perf支援直接將結果轉為火焰圖:
perf script report flamegraph -i perf.data
對於Python程式的優化，perf也有一些侷限性，因為perf不是為python定製的profiler，對python的函式呼叫，perf取樣的是CPython直譯器的呼叫棧，所以無法直接看到具體的Python函式，如下圖所示:
因此perf不太適合優化純Python程式碼，更適合觀測C/C++執行緒。此外，上面使用的perf record命令只會對程式CPU time的呼叫棧進行取樣，如果要對off-CPU time進行觀測，需要使用perf的trace命令，這裡就不詳細展開了，具體做法可以參考這篇文章: http://www.brendangregg.com/blog/2015-02-26/linux-perf-off-cpu-flame-graph.html。目前為止perf還不支援同時對CPU time和off-CPU time進行觀測，對這兩種情況只能獨立進行分析。
5.5 systemtap
systemtap是一個作業系統的動態追蹤(dynamic tracing)工具。它的功能更為強大，我們可以簡單地將systemtap視為一個可程式設計的系統級tracer。systemtap提供了一個指令碼語言，使用者可以編寫指令碼來追蹤和監控各種系統呼叫、使用者態的函式呼叫等各種自定義事件。因此使用者可以根據自己的需求，編寫指令碼來獲得程式執行中的各種需要觀測的資訊，systemtap將會使用者編寫的指令碼編譯成c程式碼，再編譯成核心模組，然後載入到正在執行的作業系統核心中。
本文不打算對systemtap進行詳細介紹，我們只關注它在profiling方面的應用（對systemtap感興趣的讀者可以參考 SystemTap Beginners Guide）此外，本文也不會展示如何編寫指令碼來實現一個profiler，openresty團隊提供了一個systemtap的工具集 (openresty-systemtap-toolkit) 可以直接拿來使用。
接下來我們介紹systemtap的安裝和上述工具集的使用方法:
安裝systemtap:
sudo apt install systemtap systemtap-runtime
除此之外，我們還需要安裝systemtap執行時的各種kernel依賴：我們可以直接執行 sudo stap-prep來安裝依賴，如果這個命令執行失敗，則需要手動安裝:
sudo apt install kernel-debuginfo-`uname -r`
sudo apt install kernel-debuginfo-common-`uname -r`
sudo apt install kernel-devel-`uname -r`
systemtap的執行需要sudo許可權，我們可以執行下面的命令來檢測安裝是否成功:
sudo stap -e \'probe begin { printf(\"Hello, World!\\n\"); exit() }\'
如果能正常輸出Hello World表示安裝成功。
使用systemtap:
我們需要用到openresty-systemtap-toolkit提供的兩個工具：sample_gt和sample_bt_off_cpu，這兩個工具分別對程式cpu time和off-cpu time的呼叫棧進行取樣:
git clone https://github.com/openresty/openresty-systemtap-toolkit.git
cd openresty-systemtap-toolkit
# 對程式cpu time的呼叫棧進行取樣, 取樣時間為10s, 取樣物件為user space呼叫棧, 並將結果儲存為cpu.bt
sudo ./sample_bt -u -t 10 -p PID > cpu.bt
# 對程式off cpu time的呼叫棧進行取樣，取樣時間為10s, 取樣物件為user space呼叫棧，並將結果儲存為off_cpu.bt
sudo ./sample_bt_off_cpu -u -t 10 -p PID > off_cpu.bt
# 命令中的-u選項指取樣user space呼叫棧，還可以選擇-k來取樣kernel space的呼叫棧；-t指取樣時間，這裡都設定為10s；-p是待取樣程式的pid
與perf類似，systemtap執行在核心態，overhead非常低。且對於python執行緒，systemtap取樣的也是CPython直譯器的呼叫棧，因此更適合觀測C/C++執行緒。
對結果進行視覺化:
視覺化方法與perf類似，flamegraph支援處理systemtap的輸出結果:
# 處理cpu.bt或off_cpu.bt
stackcollapse-stap.pl <result_dir>/cpu.bt > cpu.fold
# 可以直接在speedscope裡開啟cpu.fold，或者將其轉化為svg:
# 將perf.fold轉為svg檔案
flamegraph.pl cpu.fold > cpu.svg
5.6 eu-stack
eu-stack是elfutils(https://sourceware.org/elfutils)工具集中的一員，它的基礎功能是對一個程式的呼叫棧進行取樣:
eu-stack -p <pid>
#===== 可以得到類似下面的輸入:
#0 0x00007f5f96bbadd7 __select
#1 0x00007f5f95868278 call_readline
#2 0x0000000000425182 PyOS_Readline
#3 0x00000000004a84aa tok_nextc.cold.140
#4 0x00000000005a7774 tok_get
#5 0x00000000005a8892 parsetok
#6 0x00000000006351bd PyParser_ASTFromFileObject
#7 0x00000000004ad729 PyRun_InteractiveOneObjectEx
#8 0x00000000004afbfe PyRun_InteractiveLoopFlags
#9 0x0000000000638cb3 PyRun_AnyFileExFlags
#10 0x0000000000639671 Py_Main
#11 0x00000000004b0e40 main
#12 0x00007f5f96ac5bf7 __libc_start_main
#13 0x00000000005b2f0a _start
與perf和systemtap不同的地方是，即使程式處於off-CPU的狀態，eu-stack依然可以獲得它的C/C++呼叫棧。因此我們可以寫一個簡單的指令碼對一個執行緒的呼叫棧不斷取樣來實現一個wall clock time上的sampling based profiler。
一個簡單的profiler實現:
#!/bin/bash -xe
pid=$1
for x in $(seq 0 1000)
do
eu-stack -p $pid > d_$x.txt || true
sleep 0.2
done
eu-stack執行時不需要root許可權，執行一次的時間大約幾十毫秒，對程式的影響不算太大。
使用方法:
# 1. 安裝elfutils
sudo` `apt ``install` `elfutils
# 2. 執行上面的指令碼
.``/profiler``.sh <pid>
視覺化方法:
flamegraph裡也自帶了一個處理eu-stack輸出結果的工具，可以把採集的樣本轉為flamegraph，同樣也可以在speedscope中進行檢視：
# 假設取樣結果放在了<result_path>裡
stackcollapse-elfutils.pl <result_path>/d*txt > eu_perf.txt
# 視覺化：
# 方法1: use speedscope.app
# 直接在speedscope.app裡開啟eu_perf.txt即可
# 方法2: use flamegraph
flamegraph.pl eu_perf.txt output.svg
# 在瀏覽器裡開啟output.svg
六、例子
最後，介紹MegEngine開發過程中一個效能優化的真例項子，來展示一個從profiling到尋找bottleneck再到效能優化的流程。
在MegEngine的早期開發中我們發現某個檢測模型在單機8卡資料並行上的訓練速度非常慢，一個step的執行時間是單卡的2倍多。我們首先懷疑的是多卡間同步梯度時All Reduce的開銷帶來的影響，為了對此進行確認，我們將卡間的梯度同步關閉，使每張卡的訓練相互獨立，發現速度只提升了一點，8卡速度仍是單卡的2倍左右。
由於8卡訓練會啟動8個程式，為了徹底排除8個程式之間可能存在的聯絡帶來的干擾，我們將8卡訓練改成啟8個獨立的單卡訓練，發現速度幾乎沒有變化。此外我們還觀察到一個step的執行時間與啟動的單卡訓練的數量成正相關，啟2個單卡訓練時速度只慢了一點，4個單卡訓練慢了50%左右。
於是我們懷疑可能是8個程式之間競爭CPU資源導致了速度變慢，為了進行確認，我們對每個程式繫結相同數量的cpu核，即單程式訓練和8程式訓練中每個程式使用的CPU數量保持一致，再一次發現速度幾乎沒有變化，因此8卡速度慢與CPU資源競爭應該沒有關係。
簡單的猜測沒有定位到問題，我們打算使用profiler來查詢。MegEngine的程式可以簡化為兩個執行緒: python主執行緒和worker執行緒，其中:
- Python主執行緒: 執行python訓練指令碼，並且向佇列裡傳送任務
- worker執行緒: 是一個純C++執行緒，負責從佇列裡取任務並且執行
我們首先對Python主執行緒進行了profiling，由於希望能同時觀測到C/C++ extension，純Python profiler無法滿足我們的需求，因此我們使用了py-spy，我們開啟了--idle選項來使結果包含off cpu time上的樣本，最終得到了下面的結果:
我們發現，主執行緒大約有80%的時間花在了等待上，如上圖中的紅色框所示。有兩個地方是獲取一個tensor的numpy ndarray，單個地方是獲取一個tensor的shape，這兩種情況的等待全部都是sync worker執行緒引發的。MegEngine中主執行緒發命令和worker執行命令之間是非同步進行的，當我們需要獲得一個tensor的numpy ndarray時，則需要等worker在CUDA上完成計算並將結果copy到memory中，因此會觸發sync。另一種情況是獲得一個tensor的shape，如果某個運算元的輸出的shape無法提前推測出來，也需要等worker完稱計算才能知道，因此也會觸發sync。
由此可見主執行緒的時間幾乎都花在了等待worker上，說明worker的執行比較慢，真正的問題應該在worker執行緒上。
於是我們打算對worker執行緒進行profiling，由於worker執行緒是純C/C++執行緒，因此我們可選的工具有perf、systemtap和eu-stack，我們不確定問題出在CPU time上還是off-CPU time上，為了能夠將兩種狀態下的結果放在一起觀測，我們選擇使用eu-stack，於是獲得了以下結果:
我們發現worker執行緒居然有85%以上的時間花在了topk運算元呼叫cudaGetDeviceProperties的地方（圖中的紅色框），查閱文件後發現這個api的overhead比較大，且多程式同時呼叫時會發生io traffic競爭，因此ioctl在8程式的時間消耗過大。我們隨後修改了topk的實現 (commit)，避免呼叫cudaGetDeviceProperties，之後再次測試，發現該模型的速度回覆正常：單程式速度提升了約13%，8程式速度提升了1倍以上。
七、 參考資料
- 《Systems Performance: Enterprise and the Cloud》
- http://www.brendangregg.com/offcpuanalysis.html
- http://www.brendangregg.com/flamegraphs.html
- https://iobservable.net/blog/2013/02/03/profiler-types-and-their-overhead/
- https://blog.openresty.com.cn/cn/dynamic-tracing/
- http://qqibrow.github.io/performance-profiling-with-systemtap/
- https://www.percona.com/blog/2017/04/05/evaluation-of-profiling-tools-for-pmp/