C++ 分析技术调查:gprof vs valgrind vs perf vs gperftools
在这个答案中,我将使用几个不同的工具来分析几个非常简单的测试程序,以便具体比较这些工具的工作原理。
下面的测试程序很简单,做了以下事情:
-
main 调用fast 和maybe_slow 3 次,其中一个maybe_slow 调用速度很慢
如果我们考虑对子函数common 的调用,maybe_slow 的慢速调用要长 10 倍,并且会主导运行时。理想情况下,分析工具能够将我们指向特定的慢速调用。
-
fast 和 maybe_slow 都调用 common,这占程序执行的大部分
-
程序界面为:
./main.out [n [seed]]
并且程序总共执行O(n^2) 循环。 seed 只是为了在不影响运行时得到不同的输出。
main.c
#include <inttypes.h>
#include <stdio.h>
#include <stdlib.h>
uint64_t __attribute__ ((noinline)) common(uint64_t n, uint64_t seed) {
for (uint64_t i = 0; i < n; ++i) {
seed = (seed * seed) - (3 * seed) + 1;
}
return seed;
}
uint64_t __attribute__ ((noinline)) fast(uint64_t n, uint64_t seed) {
uint64_t max = (n / 10) + 1;
for (uint64_t i = 0; i < max; ++i) {
seed = common(n, (seed * seed) - (3 * seed) + 1);
}
return seed;
}
uint64_t __attribute__ ((noinline)) maybe_slow(uint64_t n, uint64_t seed, int is_slow) {
uint64_t max = n;
if (is_slow) {
max *= 10;
}
for (uint64_t i = 0; i < max; ++i) {
seed = common(n, (seed * seed) - (3 * seed) + 1);
}
return seed;
}
int main(int argc, char **argv) {
uint64_t n, seed;
if (argc > 1) {
n = strtoll(argv[1], NULL, 0);
} else {
n = 1;
}
if (argc > 2) {
seed = strtoll(argv[2], NULL, 0);
} else {
seed = 0;
}
seed += maybe_slow(n, seed, 0);
seed += fast(n, seed);
seed += maybe_slow(n, seed, 1);
seed += fast(n, seed);
seed += maybe_slow(n, seed, 0);
seed += fast(n, seed);
printf("%" PRIX64 "\n", seed);
return EXIT_SUCCESS;
}
gprof
gprof 需要使用仪器重新编译软件,并且它还与该仪器一起使用采样方法。因此,它在准确性(采样并不总是完全准确并且可以跳过函数)和执行速度减慢(仪器和采样是相对较快的技术,不会大大减慢执行速度)之间取得平衡。
gprof 是内置在 GCC/binutils 中的,所以我们所要做的就是使用 -pg 选项编译以启用 gprof。然后,我们使用大小 CLI 参数正常运行程序,该参数会产生合理持续时间的几秒钟 (10000):
gcc -pg -ggdb3 -O3 -std=c99 -Wall -Wextra -pedantic -o main.out main.c
time ./main.out 10000
出于教育原因,我们还将在未启用优化的情况下进行运行。请注意,这在实践中是没有用的,因为您通常只关心优化优化程序的性能:
gcc -pg -ggdb3 -O0 -std=c99 -Wall -Wextra -pedantic -o main.out main.c
./main.out 10000
首先,time 告诉我们,有和没有-pg 的执行时间是一样的,这很好:没有减速!然而,我已经看到复杂软件的 2 倍 - 3 倍减速的说法,例如作为shown in this ticket。
因为我们使用-pg 编译,所以运行程序会生成一个包含分析数据的文件gmon.out 文件。
我们可以使用gprof2dot 以图形方式观察该文件,如Is it possible to get a graphical representation of gprof results? 所要求的那样
sudo apt install graphviz
python3 -m pip install --user gprof2dot
gprof main.out > main.gprof
gprof2dot < main.gprof | dot -Tsvg -o output.svg
这里,gprof 工具读取gmon.out 跟踪信息,并在main.gprof 中生成人类可读的报告,gprof2dot 然后读取该报告以生成图表。
gprof2dot 的来源是:https://github.com/jrfonseca/gprof2dot
对于-O0 运行,我们观察到以下情况:
对于-O3 运行:
-O0 的输出几乎是不言自明的。例如,它显示 3 个maybe_slow 调用及其子调用占用了总运行时间的 97.56%,尽管 maybe_slow 本身没有子调用的执行时间占总执行时间的 0.00%,即几乎所有时间都花费在该函数中用于子调用。
TODO:为什么 -O3 输出中缺少 main,即使我可以在 GDB 中的 bt 上看到它? Missing function from GProf output 我认为这是因为 gprof 除了编译后的检测之外,也是基于采样的,而 -O3 main 太快了,没有采样。
我选择 SVG 输出而不是 PNG,因为可以使用 Ctrl + F 搜索 SVG,并且文件大小可以小 10 倍左右。此外,对于复杂的软件,生成的图像的宽度和高度可能会达到数万像素,而 GNOME eog 3.28.1 在这种情况下会出现 PNG 的错误,而 SVG 会被我的浏览器自动打开。 gimp 2.8 运行良好,另请参阅:
但即便如此,您仍需要将图像拖到很多地方才能找到所需的内容,例如,请参阅此图片来自this ticket 中的“真实”软件示例:
如果所有那些细小的未排序的意大利面条线相互重叠,您能否轻松找到最关键的调用堆栈?我敢肯定,可能会有更好的dot 选项,但我现在不想去那里。我们真正需要的是一个合适的专用查看器,但我还没有找到:
但是,您可以使用颜色图来稍微缓解这些问题。比如在之前的巨幅图像上,当我巧妙地演绎出绿色后红色,最后是越来越深的蓝色时,我终于找到了左边的关键路径。
另外,我们还可以观察我们之前保存在gprof 内置binutils 工具的文本输出:
cat main.gprof
默认情况下,这会产生一个非常详细的输出,解释输出数据的含义。既然我无法解释得比这更好,那我就让你自己看吧。
一旦您了解了数据输出格式,您就可以使用-b 选项减少冗长以仅显示数据而无需教程:
gprof -b main.out
在我们的示例中,输出为-O0:
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls s/call s/call name
100.35 3.67 3.67 123003 0.00 0.00 common
0.00 3.67 0.00 3 0.00 0.03 fast
0.00 3.67 0.00 3 0.00 1.19 maybe_slow
Call graph
granularity: each sample hit covers 2 byte(s) for 0.27% of 3.67 seconds
index % time self children called name
0.09 0.00 3003/123003 fast [4]
3.58 0.00 120000/123003 maybe_slow [3]
[1] 100.0 3.67 0.00 123003 common [1]
-----------------------------------------------
<spontaneous>
[2] 100.0 0.00 3.67 main [2]
0.00 3.58 3/3 maybe_slow [3]
0.00 0.09 3/3 fast [4]
-----------------------------------------------
0.00 3.58 3/3 main [2]
[3] 97.6 0.00 3.58 3 maybe_slow [3]
3.58 0.00 120000/123003 common [1]
-----------------------------------------------
0.00 0.09 3/3 main [2]
[4] 2.4 0.00 0.09 3 fast [4]
0.09 0.00 3003/123003 common [1]
-----------------------------------------------
Index by function name
[1] common [4] fast [3] maybe_slow
对于-O3:
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls us/call us/call name
100.52 1.84 1.84 123003 14.96 14.96 common
Call graph
granularity: each sample hit covers 2 byte(s) for 0.54% of 1.84 seconds
index % time self children called name
0.04 0.00 3003/123003 fast [3]
1.79 0.00 120000/123003 maybe_slow [2]
[1] 100.0 1.84 0.00 123003 common [1]
-----------------------------------------------
<spontaneous>
[2] 97.6 0.00 1.79 maybe_slow [2]
1.79 0.00 120000/123003 common [1]
-----------------------------------------------
<spontaneous>
[3] 2.4 0.00 0.04 fast [3]
0.04 0.00 3003/123003 common [1]
-----------------------------------------------
Index by function name
[1] common
作为每个部分的快速总结,例如:
0.00 3.58 3/3 main [2]
[3] 97.6 0.00 3.58 3 maybe_slow [3]
3.58 0.00 120000/123003 common [1]
以左缩进的函数为中心 (maybe_flow)。 [3] 是该函数的 ID。函数上方是调用者,下方是被调用者。
对于-O3,请参见此处,就像在图形输出中maybe_slow 和fast 没有已知的父级,这就是文档所说的<spontaneous> 的意思。
我不确定是否有使用 gprof 进行逐行分析的好方法:`gprof` time spent in particular lines of code
valgrind 调用研磨
valgrind 通过 valgrind 虚拟机运行程序。这使得分析非常准确,但它也会导致程序非常慢。我之前也提到过 kcachegrind:Tools to get a pictorial function call graph of code
callgrind 是 valgrind 的代码分析工具,kcachegrind 是一个可以可视化 cachegrind 输出的 KDE 程序。
首先我们必须删除-pg 标志才能恢复正常编译,否则运行实际上会失败并显示Profiling timer expired,是的,这很常见,以至于我这样做了,并且有一个堆栈溢出问题。
所以我们编译运行如下:
sudo apt install kcachegrind valgrind
gcc -ggdb3 -O3 -std=c99 -Wall -Wextra -pedantic -o main.out main.c
time valgrind --tool=callgrind valgrind --dump-instr=yes \
--collect-jumps=yes ./main.out 10000
我启用--dump-instr=yes --collect-jumps=yes 是因为这还会转储信息,使我们能够以相对较小的额外开销成本查看每个装配线的性能细分。
马上,time 告诉我们程序执行需要 29.5 秒,因此在这个示例中我们的速度降低了大约 15 倍。显然,这种放缓将成为更大工作负载的严重限制。在“真实世界软件示例”mentioned here 中,我观察到速度下降了 80 倍。
运行会生成一个名为 callgrind.out.<pid> 的配置文件数据文件,例如callgrind.out.8554 就我而言。我们通过以下方式查看该文件:
kcachegrind callgrind.out.8554
它显示了一个 GUI,其中包含类似于文本 gprof 输出的数据:
此外,如果我们转到右下角的“调用图”选项卡,我们会看到一个调用图,我们可以通过右键单击它来导出以下带有不合理数量的白色边框的图像:-)
我认为fast 没有显示在该图表上,因为 kcachegrind 必须简化了可视化,因为该调用占用的时间太少,这可能是您在真实程序上想要的行为。右键菜单有一些设置来控制何时剔除此类节点,但我无法让它在快速尝试后显示如此短的调用。如果我单击左侧窗口中的fast,它会显示带有fast 的调用图,因此实际上捕获了该堆栈。还没有人找到显示完整图调用图的方法:Make callgrind show all function calls in the kcachegrind callgraph
复杂 C++ 软件上的 TODO,我看到一些 <cycle N> 类型的条目,例如<cycle 11> 我期望函数名称,这是什么意思?我注意到有一个“循环检测”按钮可以打开和关闭它,但这是什么意思?
perf 来自linux-tools
perf 似乎只使用 Linux 内核采样机制。这使得设置非常简单,但也不完全准确。
sudo apt install linux-tools
time perf record -g ./main.out 10000
这增加了 0.2 秒的执行时间,所以我们在时间上很好,但在使用键盘右箭头扩展 common 节点后,我仍然没有看到太多的兴趣:
Samples: 7K of event 'cycles:uppp', Event count (approx.): 6228527608
Children Self Command Shared Object Symbol
- 99.98% 99.88% main.out main.out [.] common
common
0.11% 0.11% main.out [kernel] [k] 0xffffffff8a6009e7
0.01% 0.01% main.out [kernel] [k] 0xffffffff8a600158
0.01% 0.00% main.out [unknown] [k] 0x0000000000000040
0.01% 0.00% main.out ld-2.27.so [.] _dl_sysdep_start
0.01% 0.00% main.out ld-2.27.so [.] dl_main
0.01% 0.00% main.out ld-2.27.so [.] mprotect
0.01% 0.00% main.out ld-2.27.so [.] _dl_map_object
0.01% 0.00% main.out ld-2.27.so [.] _xstat
0.00% 0.00% main.out ld-2.27.so [.] __GI___tunables_init
0.00% 0.00% main.out [unknown] [.] 0x2f3d4f4944555453
0.00% 0.00% main.out [unknown] [.] 0x00007fff3cfc57ac
0.00% 0.00% main.out ld-2.27.so [.] _start
然后我尝试对-O0 程序进行基准测试以查看它是否显示任何内容,直到现在,我终于看到了调用图:
Samples: 15K of event 'cycles:uppp', Event count (approx.): 12438962281
Children Self Command Shared Object Symbol
+ 99.99% 0.00% main.out [unknown] [.] 0x04be258d4c544155
+ 99.99% 0.00% main.out libc-2.27.so [.] __libc_start_main
- 99.99% 0.00% main.out main.out [.] main
- main
- 97.54% maybe_slow
common
- 2.45% fast
common
+ 99.96% 99.85% main.out main.out [.] common
+ 97.54% 0.03% main.out main.out [.] maybe_slow
+ 2.45% 0.00% main.out main.out [.] fast
0.11% 0.11% main.out [kernel] [k] 0xffffffff8a6009e7
0.00% 0.00% main.out [unknown] [k] 0x0000000000000040
0.00% 0.00% main.out ld-2.27.so [.] _dl_sysdep_start
0.00% 0.00% main.out ld-2.27.so [.] dl_main
0.00% 0.00% main.out ld-2.27.so [.] _dl_lookup_symbol_x
0.00% 0.00% main.out [kernel] [k] 0xffffffff8a600158
0.00% 0.00% main.out ld-2.27.so [.] mmap64
0.00% 0.00% main.out ld-2.27.so [.] _dl_map_object
0.00% 0.00% main.out ld-2.27.so [.] __GI___tunables_init
0.00% 0.00% main.out [unknown] [.] 0x552e53555f6e653d
0.00% 0.00% main.out [unknown] [.] 0x00007ffe1cf20fdb
0.00% 0.00% main.out ld-2.27.so [.] _start
TODO:-O3 执行时发生了什么?难道仅仅是maybe_slow 和fast 太快了,没有得到任何样本吗? -O3 在需要更长执行时间的大型程序上是否能正常工作?我错过了一些 CLI 选项吗?我发现-F 可以控制以赫兹为单位的采样频率,但我将其调高到默认允许的最大值-F 39500(可以使用sudo 增加),我仍然看不到清晰的调用。
perf 的一个很酷的地方是 Brendan Gregg 的 FlameGraph 工具,它以非常简洁的方式显示调用堆栈时间,让您可以快速查看大调用。该工具位于:https://github.com/brendangregg/FlameGraph,并且在他的性能教程中也提到:http://www.brendangregg.com/perf.html#FlameGraphs 当我在没有sudo 的情况下运行perf 时,我得到了ERROR: No stack counts found,所以现在我将使用sudo :
git clone https://github.com/brendangregg/FlameGraph
sudo perf record -F 99 -g -o perf_with_stack.data ./main.out 10000
sudo perf script -i perf_with_stack.data | FlameGraph/stackcollapse-perf.pl | FlameGraph/flamegraph.pl > flamegraph.svg
但是在这样一个简单的程序中,输出并不是很容易理解,因为我们不能轻易地在该图上看到maybe_slow 和fast:
在一个更复杂的例子中,图表的含义就很清楚了:
TODO 在那个例子中有一个[unknown] 函数的日志,这是为什么呢?
另一个可能值得的 perf GUI 界面包括:
gperftools
以前称为“Google 性能工具”,来源:https://github.com/gperftools/gperftools 基于示例。
首先安装 gperftools:
sudo apt install google-perftools
然后,我们可以通过两种方式启用 gperftools CPU 分析器:在运行时或在构建时。
在运行时,我们必须将LD_PRELOAD 设置为指向libprofiler.so,您可以使用locate libprofiler.so 找到它,例如在我的系统上:
gcc -ggdb3 -O3 -std=c99 -Wall -Wextra -pedantic -o main.out main.c
LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libprofiler.so \
CPUPROFILE=prof.out ./main.out 10000
或者,我们可以在链接时构建库,在运行时分配传递 LD_PRELOAD:
gcc -Wl,--no-as-needed,-lprofiler,--as-needed -ggdb3 -O3 -std=c99 -Wall -Wextra -pedantic -o main.out main.c
CPUPROFILE=prof.out ./main.out 10000
另请参阅:gperftools - profile file not dumped
到目前为止,我发现查看这些数据的最佳方法是使 pprof 输出与 kcachegrind 作为输入相同的格式(是的,Valgrind-project-viewer-tool)并使用 kcachegrind 来查看:
google-pprof --callgrind main.out prof.out > callgrind.out
kcachegrind callgrind.out
使用其中任何一种方法运行后,我们都会得到一个prof.out 配置文件数据文件作为输出。我们可以通过以下方式将该文件以图形方式查看为 SVG:
google-pprof --web main.out prof.out
它提供了与其他工具一样熟悉的调用图,但使用笨重的样本数单位而不是秒。
或者,我们也可以通过以下方式获取一些文本数据:
google-pprof --text main.out prof.out
给出:
Using local file main.out.
Using local file prof.out.
Total: 187 samples
187 100.0% 100.0% 187 100.0% common
0 0.0% 100.0% 187 100.0% __libc_start_main
0 0.0% 100.0% 187 100.0% _start
0 0.0% 100.0% 4 2.1% fast
0 0.0% 100.0% 187 100.0% main
0 0.0% 100.0% 183 97.9% maybe_slow
另见:How to use google perf tools
使用原始 perf_event_open 系统调用来检测您的代码
我认为这与 perf 使用的底层子系统相同,但您当然可以通过在编译时使用感兴趣的事件显式检测程序来获得更大的控制权。
这对大多数人来说可能太硬核了,但它很有趣。最小可运行示例:Quick way to count number of instructions executed in a C program
英特尔 VTune
https://en.wikipedia.org/wiki/VTune
这似乎是封闭源代码且仅限 x86,但从我所听到的情况来看,它可能是惊人的。我不确定它的使用免费程度,但它似乎可以免费下载。 TODO 评估。
在 Ubuntu 18.04、gprof2dot 2019.11.30、valgrind 3.13.0、perf 4.15.18、Linux 内核 4.15.0、FLameGraph 1a0dc6985aad06e76857cf2a354bd5ba0c9ce96b、gperftools 2.5-2 中测试。