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:

4.2 speedscope

另外一个值得介绍的工具是speedscope。speedscope的使用方法和flamegraph类似，且兼容flamegraph的输出格式。与flamegraph相比，speedscope在两个方面具有优势: 1) speedscope在可视化效果、交互性等方面表现十分优秀，2) speedscope运行时的开销比SVG低很多，同时开很多窗口也不会造成明显卡顿。因此，我们推荐把speedscope与flamegraph结合在一起使用: 用flamegraph来处理不同工具的输出数据，用speedscope进行可视化。speedscope是一个web app，作者提供了一个可以直接使用的地址: //www.speedscope.app/, 我们也可以在本地部署，但更前者更方便。本文主要以speedscope来可视化profiling结果，下面简单介绍一下它的使用方法:

进入//www.speedscope.app/中，打开json格式的profiling结果 (我们会在下面各种profiler的使用方法中介绍如何将结果转为这种json)。可以看到以下界面 (与flamegraph的一个不同之处是speedscope的调用栈是倒过来的):

左上角可以选择三种模式:

  • Time Order: 即时间轴模式，从左到右代表时间的方向，中间每一列代表改时刻采样的调用栈
  • Left Heavy: 按照调用栈函数的时间占比(采样次数占比来估计时间占比)进行展示，即调用栈的每一层都按照左侧时间多右侧时间短的顺序来排序。点击任何一个调用栈中的函数:
    • 可以在图中左下角看到该函数在当前调用栈(This Instance)的总开销(Total) 和自身开销(Self)，以及该函数在所有出现过的调用栈(All Instances)中的总开销(Total)和自身开销(Self), 图中的整数代表被采样的次数，百分比为被采样的占比(近似等于时间占比)。
    • 图下方的白色框内是该函数的调用栈。
  • Sandwich:用函数的总开销和自身开销来排序，点击函数可以看到该函数的调用者和被调用者

更详细的介绍可以参考speedscope的官方repo: //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: //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进程的调用栈。具体使用方法可以参考文档: //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：//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文档: //docs.python.org/3/library/profile.html

5.3 pyinstrument

pyinstrument是一个sampling based profiler，功能上与cProfile类似，只支持Sampling纯Python调用栈，类似地只支持wall clock time，但overhead相对cProfile低一些，且自带多种可视化方法。

官方repo地址: //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 //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命令，这里就不详细展开了，具体做法可以参考这篇文章: //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 //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(//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倍以上。

七、 参考资料

Tags:

VirMach 便宜 VPS

QNews

QNews