Python 和 C/C++ 拓展程序的性能优化（下）-博客-MegEngine

tips:文章上部分请点击：python和c/c++拓展程序的性能优化（上）-博客-天元MegEngine

五、性能观测工具

接下来我们介绍几个在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/