Python 和 C/C++ 拓展程序如何性能優化？看這一篇文就夠

作者：王璐璐 | 曠視 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/