如何找到在Linux上运行的C++应用程序中运行缓慢的代码区域?
当前回答
这是对Nazgob Gprof回答的回应。
过去几天我一直在使用Gprof,已经发现了三个重要的限制,其中一个是我在其他地方还没有看到过的:
它不能在多线程代码上正常工作,除非您使用变通方法调用图被函数指针弄糊涂了。示例:我有一个名为multithread()的函数,它使我能够在指定的数组上对指定的函数进行多线程处理(两者都作为参数传递)。然而,Gprof将所有对多线程()的调用视为等效的,以计算在孩子身上花费的时间。由于我传递给多线程()的一些函数花费的时间比其他函数长得多,所以我的调用图基本上是无用的。(对于那些想知道线程是否是这里的问题的人来说:不,多线程()可以选择,在这种情况下,只在调用线程上按顺序运行所有内容)。这里说“……调用数数字是通过计数而不是采样得出的。它们是完全准确的……”。然而,我发现我的调用图给了我5345859132+784984078作为对我调用最多的函数的调用统计数据,其中第一个数字应该是直接调用,第二个递归调用(都来自它本身)。因为这意味着我有一个bug,所以我在代码中加入了长(64位)计数器,并再次运行相同的程序。我的计数:5345859132个直接调用和78094395406个自递归调用。这里有很多数字,所以我要指出,我测量的递归调用是780亿,而Gprof是7.84亿:相差100倍。两次运行都是单线程和未优化的代码,一次是编译的-g,另一次是-pg。
这是在64位Debian Lenny下运行的GNUGprof(Debian的GNUBinutils)2.18.0.20080103,如果这对任何人都有帮助的话。
其他回答
我假设你在使用GCC。标准的解决方案是使用gprof进行分析。
在分析之前,请确保将-pg添加到编译中:
cc -o myprog myprog.c utils.c -g -pg
我还没有尝试过,但我听到了关于谷歌perftools的好消息。这绝对值得一试。
这里有相关问题。
如果gprof不适合您,还有一些流行语:Valgrind、Intel VTune、Sun DTrace。
使用Valgrind、callgrind和kcachegrind:
valgrind --tool=callgrind ./(Your binary)
生成callgrind.out.x。使用kcachegrind读取它。
使用gprof(add-pg):
cc -o myprog myprog.c utils.c -g -pg
(对于多线程、函数指针不太好)
使用google perftools:
使用时间采样,可以发现I/O和CPU瓶颈。
英特尔VTune是最好的(出于教育目的免费)。
其他:AMD Codeanalysis(已被AMD CodeXL取代)、OProfile、“perf”工具(apt-get-install-linux工具)
C++评测技术综述:gprof vs valgrind vs perf vs gperftools
在这个答案中,我将使用几种不同的工具来分析一些非常简单的测试程序,以便具体比较这些工具的工作方式。
以下测试程序非常简单,可执行以下操作:
main调用fast和maybe_slow 3次,其中一个maybe_slow调用很慢maybe_slow的慢调用要长10倍,如果我们考虑到对子函数的调用是公共的,那么它在运行时占主导地位。理想情况下,分析工具将能够将我们指向特定的慢速调用。fast和maybe_slow调用都是公共的,这占了程序执行的大部分程序界面为:./main.out[n[seed]]程序总共执行O(n^2)个循环。seed只是在不影响运行时的情况下获得不同的输出。
主.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
首先,时间告诉我们,使用和不使用-pg的执行时间是相同的,这很好:没有减速!然而,我已经看到复杂软件的速度下降了2倍到3倍,如这张罚单所示。
因为我们是用-pg编译的,所以运行该程序会生成一个包含评测数据的文件gmon.out。
我们可以用gprof2dot以图形方式观察该文件,如以下问题所问:是否可以获得gprof结果的图形表示?
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上看到它?GProf输出中缺少函数,我认为这是因为GProf除了编译的工具外,还基于采样,而且-O3 main太快,没有采样。
我选择SVG输出而不是PNG,因为SVG可以用Ctrl+F搜索,文件大小可以小10倍。此外,对于复杂的软件,生成的图像的宽度和高度可以是数万像素,而GNOME eog 3.28.1在这种情况下对于PNG是错误的,而SVG会被我的浏览器自动打开。gimp 2.8运行良好,另请参见:
https://askubuntu.com/questions/1112641/how-to-view-extremely-large-imageshttps://unix.stackexchange.com/questions/77968/viewing-large-image-on-linuxhttps://superuser.com/questions/356038/viewer-for-huge-images-under-linux-100-mp-color-images
但即使如此,您仍将拖动图像以找到所需的内容,例如,此图像来自取自此票据的“真实”软件示例:
你能很容易地找到最关键的调用堆栈吗?我肯定可能有更好的圆点选项,但我现在不想去那里。我们真正需要的是一个合适的专用观众,但我还没有找到:
在kcachegrind中查看gprof输出哪个是KProf的最佳替代品?
然而,您可以使用颜色映射来稍微缓解这些问题。例如,在前一张巨大的图片上,我终于找到了左边的关键路径,我做出了一个绝妙的推论,即绿色在红色之后,最后是越来越深的蓝色。
或者,我们也可以观察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,请参见这里的图形输出,可能是因为slow和fast没有已知的父级,这就是文档中所说的<自发性>的意思。
我不确定是否有一种很好的方法可以用gprof进行逐行分析:“gprof”在特定代码行上花费的时间
valgrind callgrind公司
valgrind通过valgrind虚拟机运行程序。这使得分析非常准确,但也会导致程序的大幅减速。我之前也提到过kcachegrind:获取代码的图形函数调用图的工具
callgrind是valgrind分析代码的工具,kcachegrind是一个KDE程序,可以可视化cachegrind输出。
首先,我们必须删除-pg标志以返回正常编译,否则运行实际上会失败,评测计时器已过期,是的,这是很常见的,我这样做了,并且存在堆栈溢出问题。
因此,我们编译并运行为:
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,因为这也会转储信息,使我们能够以相对较小的额外开销成本查看每个装配线的性能细分。
不经意间,时间告诉我们程序执行需要29.5秒,所以在这个例子中,我们的速度减慢了大约15倍。显然,对于更大的工作负载来说,这种放缓将是一个严重的限制。在这里提到的“真实世界软件示例”中,我观察到了80倍的速度。
运行会生成一个名为callgrind.out.<pid>的配置文件数据文件,例如callgrind_out.8554。我们通过以下方式查看该文件:
kcachegrind callgrind.out.8554
其显示了包含与文本gprof输出类似的数据的GUI:
此外,如果我们转到右下角的“调用图”选项卡,我们会看到一个调用图,通过右键单击它可以导出该调用图,以获得以下带有不合理数量的白色边框的图像:-)
我认为fast没有显示在图表上,因为kcachegrind必须简化了可视化,因为调用占用的时间太少,这很可能是您在实际程序中想要的行为。右键单击菜单有一些设置来控制何时选择这样的节点,但我无法在快速尝试后显示如此短的调用。如果我单击左侧窗口上的fast,它会显示一个带有fast的调用图,所以堆栈实际上被捕获了。还没有人找到显示完整图形调用图的方法:让callgrind显示kcachegrind调用图中的所有函数调用
在复杂的C++软件上的TODO中,我看到了一些<cycle N>类型的条目,例如<cycle 11>,我期望的是函数名,这意味着什么?我注意到有一个“循环检测”按钮可以打开和关闭,但这意味着什么?
linux工具的性能
perf似乎只使用Linux内核采样机制。这使得设置非常简单,但也不完全准确。
sudo apt install linux-tools
time perf record -g ./main.out 10000
这增加了0.2秒的执行时间,因此我们在时间上很好,但在使用键盘右箭头扩展公共节点之后,我仍然看不到太多的兴趣:
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时发生了什么?难道只是因为速度太快,没有得到任何样本吗?在执行时间较长的大型程序上,它与-O3配合使用是否良好?我错过了一些CLI选项吗?我找到了-F来控制以赫兹为单位的采样频率,但我将其设置为默认允许的最大值-F 39500(可以使用sudo增加),我仍然看不到清晰的调用。
perf的一个很酷的地方是Brendan Gregg的FlameGraph工具,它以非常整洁的方式显示调用堆栈计时,让您可以快速看到大型调用。该工具位于:https://github.com/brendangregg/FlameGraph在他的perf教程中也有提到:http://www.brendangregg.com/perf.html#FlameGraphs当我在没有sudo的情况下运行perf时,我得到了错误:没有找到堆栈计数,所以现在我将使用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
但在这样一个简单的程序中,输出不太容易理解,因为我们不能很容易地在该图上看到既慢又快:
在一个更复杂的例子中,图表的含义变得清晰:
TODO在该示例中有一个[未知]函数的日志,这是为什么?
另一个值得使用的性能GUI界面包括:
Eclipse Trace Compass插件:https://www.eclipse.org/tracecompass/但这有一个缺点,即您必须首先将数据转换为公共跟踪格式,这可以通过perf数据来完成,即转换为ctf,但它需要在构建时启用/具有足够的perf new,这两种情况都不适用于Ubuntu 18.04中的perfhttps://github.com/KDAB/hotspot这样做的缺点是似乎没有Ubuntu软件包,构建它需要Qt 5.10,而Ubuntu 18.04的Qt 5.9。但David Faure在评论中提到,没有AppImage包,这可能是一种方便的使用方法。
gperftools软件
以前称为“谷歌性能工具”,来源:https://github.com/gperftools/gperftools基于样本。
首先安装gperftools:
sudo apt install google-perftools
然后,我们可以通过两种方式启用gperftools CPU分析器:在运行时或在构建时。
在运行时,我们必须传递设置LD_PRELOAD以指向libprofiler.so,您可以通过查找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-配置文件未转储
到目前为止,查看这些数据的最佳方法是使pprof输出与kcachegrind作为输入的格式相同(是的,Valgrind项目查看器工具),并使用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
另请参阅:如何使用google perf工具
使用原始perf_event_open系统调用检测代码
我认为这是perf使用的同一个底层子系统,但您当然可以通过在编译时使用感兴趣的事件显式地检测程序来获得更大的控制。
对大多数人来说,这可能太过于硬核了,但这是一种乐趣。最小可运行示例:快速计算C程序中执行的指令数
英特尔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、gperftools2.5-2中测试。
您可以使用loguru这样的日志框架,因为它包括时间戳和总运行时间,可以很好地用于分析:
您可以使用iprof库:
https://gitlab.com/Neurochrom/iprof
https://github.com/Neurochrom/iprof
它是跨平台的,允许您不实时测量应用程序的性能。您甚至可以将其与实时图表相结合。完整免责声明:我是作者。