如何找到在Linux上运行的C++应用程序中运行缓慢的代码区域?


当前回答

我会使用Valgrind和Callgrind作为我的仿形工具套件的基础。重要的是,Valgrind基本上是一台虚拟机:

(维基百科)Valgrind本质上是虚拟的机器使用准时制(JIT)编译技术,包括动态重新编译。没有来自的内容原始程序始终运行直接在主机处理器上。相反,Valgrind首先翻译将程序转换为临时的、更简单的形式称为中间表示(IR)是处理器中性的,转换后,工具(见下文)可以自由使用无论它想要什么样的转变在Valgrind翻译之前IR返回到机器代码中主机处理器运行它。

Callgrind是一个基于此的剖析器。主要的好处是,您不必运行应用程序数小时就能获得可靠的结果。因为Callgrind是一个非探测型剖面仪,所以即使一秒钟的运行也足以获得可靠的结果。

另一个基于Valgrind的工具是Massif。我使用它来分析堆内存使用情况。它工作得很好。它的作用是为您提供内存使用情况的快照--详细信息What hold What percentage of memory,and WHO has put it there。这些信息在应用程序运行的不同时间点可用。

其他回答

较新的内核(例如最新的Ubuntu内核)附带了新的“perf”工具(apt-get-install-linux-tools)AKA perf_events。

这些都配有经典的采样分析器(手册页)以及很棒的时间图表!

重要的是,这些工具可以是系统评测,而不仅仅是进程评测-它们可以显示线程、进程和内核之间的交互,并让您了解进程之间的调度和I/O依赖关系。

对于单线程程序,您可以使用igprof,The Ignorminous Profiler:https://igprof.org/ .

这是一个采样分析器,沿着。。。长的Mike Dunlavey的回答,它将把结果包装在一个可浏览的调用堆栈树中,用每个函数(无论是累积的还是每个函数)花费的时间或内存进行注释。

在工作中,我们有一个非常好的工具,它可以帮助我们监控我们想要的日程安排。这已多次有用。

它是用C++编写的,必须根据您的需要进行定制。不幸的是,我不能共享代码,只有概念。您使用一个包含时间戳和事件ID的“大”易失性缓冲区,可以在死后或停止日志系统后转储(例如,将其转储到文件中)。

您检索包含所有数据的所谓大缓冲区,一个小接口解析它并显示带有名称(up/down+value)的事件,就像示波器使用颜色(在.hpp文件中配置)所做的那样。

您可以自定义生成的事件数量,以仅关注您所需的内容。它帮助我们解决了调度问题,同时根据每秒记录的事件数量消耗了所需的CPU数量。

您需要3个文件:

toolname.hpp // interface
toolname.cpp // code
tool_events_id.hpp // Events ID

其概念是在tool_events_id.hpp中定义如下事件:

// EVENT_NAME                         ID      BEGIN_END BG_COLOR NAME
#define SOCK_PDU_RECV_D               0x0301  //@D00301 BGEEAAAA # TX_PDU_Recv
#define SOCK_PDU_RECV_F               0x0302  //@F00301 BGEEAAAA # TX_PDU_Recv

您还可以在toolname.hpp中定义一些函数:

#define LOG_LEVEL_ERROR 0
#define LOG_LEVEL_WARN 1
// ...

void init(void);
void probe(id,payload);
// etc

代码中可以使用的任何位置:

toolname<LOG_LEVEL>::log(EVENT_NAME,VALUE);

probe函数使用几条装配线尽快检索时钟时间戳,然后在缓冲区中设置一个条目。我们还有一个原子增量来安全地找到存储日志事件的索引。当然,缓冲区是圆形的。

希望这个想法不会因为缺少示例代码而混淆。

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中测试。

我会使用Valgrind和Callgrind作为我的仿形工具套件的基础。重要的是,Valgrind基本上是一台虚拟机:

(维基百科)Valgrind本质上是虚拟的机器使用准时制(JIT)编译技术,包括动态重新编译。没有来自的内容原始程序始终运行直接在主机处理器上。相反,Valgrind首先翻译将程序转换为临时的、更简单的形式称为中间表示(IR)是处理器中性的,转换后,工具(见下文)可以自由使用无论它想要什么样的转变在Valgrind翻译之前IR返回到机器代码中主机处理器运行它。

Callgrind是一个基于此的剖析器。主要的好处是,您不必运行应用程序数小时就能获得可靠的结果。因为Callgrind是一个非探测型剖面仪,所以即使一秒钟的运行也足以获得可靠的结果。

另一个基于Valgrind的工具是Massif。我使用它来分析堆内存使用情况。它工作得很好。它的作用是为您提供内存使用情况的快照--详细信息What hold What percentage of memory,and WHO has put it there。这些信息在应用程序运行的不同时间点可用。