C++ Profiler工具之初体验

概要：本文同期调研了google profile工具以及其他常用profile的工具，如GNU gprof、oprofile等(都是开源项目)，并对其实现原理做了简单分析和比较。希望对之后的推广使用或二期开发有所帮助。

一、 GUN Gropf

Gprof是GNU profiler工具。可以显示程序运行的“flatprofile”，包括每个函数的调用次数，每个函数消耗的处理器时间。也可以显示“调用图”，包括函数的调用关系，每个函数调用花费了多少时间。还可以显示“注释的源代码”，是程序源代码的一个复本，标记有程序中每行代码的执行次数。关于Gprof的使用以及实现原理网上已有多篇文章提及，本文就不再详述，只是对其进行梳理和总结，方便阅读。（Gprof的官方网址：http://www.cs.utah.edu/dept/old/texinfo/as/gprof_toc.html，http://sourceware.org/binutils/docs/gprof/index.html 绝对权威的参考资料。）

1.1 安装

Glibc自带，无需另外安装

1.2 用法

参考http://hi.baidu.com/juventus/blog/item/312dd42a0faf169b033bf6ff.html/cmtid/3c34349bb5a8ceb8c9eaf4c5

图形化输出请参考大师blog：http://www.51testing.com/?uid-13997-action-viewspace-itemid-79952

1.3 实现原理

引用官网说明：

当我们使用"-pg" 选项编译程序后，gcc会做三个工作：

1. 程序的入口处(main 函数之前)插入monstartup函数的调用代码，完成profile的初始化工作，包括分配保存信息的内存以及设置一个clock 信号处理函数；

2. 在每个函数的入口处插入_mcount函数的调用代码，用于统计函数的调用信息：包括调用时间、调用次数以及调用栈信息；

3. 在程序退出时(在 atexit () 里)插入_mcleanup()函数的调用代码，负责将profile信息输出到gmon.out中。

这些过程可以通过objdump反汇编显示出来：

objdump -S a.out

0000000000400aba<main>:

400aba: 55 push %rbp

400abb: 48 89e5 mov %rsp,%rbp

400abe: 48 83 ec20 sub $0x20,%rsp

400ac2: e8 69 fd ffff callq 400830<mcount@plt>

......

可以看出，在main函数的入口插入了一行汇编代码：callq 400830 <mcount@plt> ，这样main函数的第一行执行代码就是调用_mcount函数。

我们接下来再看看glibc的这三个函数具体都做了什么：

a ) __monstartup 此函数的定义在glibc的gmon/gmon.c中

linux系统中，__monstartup是在__gmon_start__ 中调用的。在程序链接过程中，gcc用gcrt0.o替代了默认的crt0.o，从而修改了main函数执行前的初始化工作：

__gmon_start__的定义在csu/gmon-start.c中

__gmon_start__ 不仅调用了__monstartup函数，还注册了一个清理函数_mcleanup，此函数将在程序结束时被调用。_mcleanup的功能会在后续说明，接下来让我们看看__monstartup函数都做了什么。

可以看书，函数中的大部分代码都是在做初始化工作，为profile信息分配存储空间，它的两个参数lowpc，highpc（通过调试可以得知lowpc起始是程序代码段的起始地址，而highpc是程序代码段的结束地址，&etext），分别代表了需要记录profile信息的地址范围，超过这个范围的地址，gprof是不会记录profile信息的。这也解释了为何gprof不能支持对动态库的解析，以为动态库的装载是在程序代码段之外的。我们通过一个实例可以证明这一点。

以一个简单的测试程序为例：

编译生成./test可执行程序。我们用readelf工具获取test文件的段信息，

readelf -S test

从输出可以看出，test可执行程序的text代码地址为0x400540 ~ 0x400540 + 0x278。

接下来运行./test ，通过对glibc代码的修改，我们打印出__monstartup函数的两个实参值，结果如下：

lowpc: 400540, highpc: 4007c6，正好对应着test程序的代码段范围。

同时我们也dump出test程度在内存中的装载地址：

cat /proc/$self/maps:

test装载到内存的地址范围为00400000-00401000，为libc.so装载到内存的地址范围为2b4f1af25000-2b4f1b063000，现在不在lowpc和highpc范围之内，所以libc中的函数是不会被gprof解析的。

__monstartup函数的最后会调用__moncontrol函数来设置一个clock信号处理函数用于设置提取sample。

__moncontrol的定义在glibc的gmon/gmon.c中

其中__profil的定义在sysdeps/posix/profil.c中

这个函数的主要作用就是定义了一个SIGPROF信号处理函数，并通过__setitimer函数设置SIGPROF的发送频率。这个信号处理函数的功能很关键，后续仍会说明。

b）_mcount 此函数的定义在sysdeps/generic/machine-gmon.h中

其中((u_long) RETURN_ADDRESS (nr)调用了__builtin_return_address(nr)函数，__builtin_return_address(nr)会返回当前调用栈中第nr帧的pc地址。所以(u_long)RETURN_ADDRESS (0)返回的是当前函数地址topc；而(u_long) RETURN_ADDRESS(1)返回的是当前函数的返回地址frompc。

mcount_internal的定义在gmon/mcont.c中

此函数的主要功能就是记录每个函数的调用次数，以及函数之间的调用关系表。并将这些信息保存在全局变量_gmonparam中。由于此函数是通过hack的方式来调用的（插入入口代码），因此其获取的信息都是精确的。强调z这一点的目的是为了下面将要介绍的另一个主要函数: profil_counter 。回溯到gcc的一个步骤，monstartup函数在初始化的最后阶段，通过sigaction调用注册了一个SIGPROF信号处理函数，这个函数profil_counter。这个函数会以__profile_frequency()的频率被调用，并完成profile的主要工作：收集sample信息，以此来计算每个函数的消耗时间。

profil_counter函数的定义依赖于具体的系统平台，X86_64平台下的定义是在sysdeps/unix/sysv/linux/x86_64/profil-counter.h中

其最终调用的profil_count定义在sysdeps/posix/profil.c中

这段代码的逻辑有点晦涩，需要联系之前的处理逻辑来理解。pc_offset、pc_scale以及samples这些全局变量的赋值是在__profil函数中处理的。回溯__profil的逻辑代码，就可以看出samples=_gmonparam->kcount, 用于保存sample信息，pc_offset =p->lowpc，是程序代码段的起始地址，pc_scale是一个比例因子，用于控制sample的提取粒度。综合上下文，gprof在这里的处理逻辑是将lowpc~lowpc+65536（linux下默认一个段的大小为64K）范围内的代码映射到一个内存数组，而pc_scale其实就是决定了映射粒度。对于任何一个处于[lowpc,lowpc+65536]范围内的pc，其对应的数组下标是: pc - lowpc / (65536/ pc_scale) = (pc - lowpc) * pc_scale /65536;这样一个数组项（一个sample）对应了一段pc_scale长度的程序地址，而每当这段地址内的代码被执行时，相应的sample计数就会加1。

c ) 最后当程序结束时，会调用_mcleanup，其定义在gmon/gmon.c中。

首先其通过__moncontrol（0）结束profil工作，其次通过write_gmon ()函数将profile信息输出到gmon.out文件中。

write_gmo函数的定义在gmon/gmon.c中

通过write_hist、write_call_graph、write_bb_counts这三个子函数，其分别将pc histogram、call-graph以及basic-block execution counts信息输出到gmon.out中。

1.4 gprof的输出分析

在gmon.out文件产生之后，可以通过GNU binutils中提供的工具gprof来分析数据，转换成容易阅读、理解的格式（文字、图片等）。

gprof的主要代码在gprof/gprof.c中

在gmon_out_read函数中，其分别通过hist_read_rec、cg_read_rec、bb_read_rec来读取gmon.out中对应的pc histogram、call-graph以及basic-block executioncounts信息。在将pchistogram映射到具体函数时间的处理上，gprof采用了一种近似算法：

其中，bin_low_pc待用sample数组中的任意一项所对应的PC地址：而bin_high_pc代表bin_low_pc下一个sample对应的PC地址：

bin_low_pc = lowpc + (bfd_vma)(hist_scale * i);

bin_high_pc = lowpc +(bfd_vma) (hist_scale * (i + 1));

sym_low_pc待用可执行程序中某个符号（函数名、段名等）所对应的PC地址，sym_high_pc为下一个符号项所对应的PC地址：

sym_low_pc =symtab.base[j].hist.scaled_addr;

sym_high_pc = symtab.base[j +1].hist.scaled_addr;

gprof只将[bin_low_pc, bin_high_pc]和[sym_low_pc ,sym_high_pc]重合区域（以箭头标识）的sample次数算为sym_low_pc符号的消耗时间。

overlap = MIN (bin_high_pc,sym_high_pc) - MAX (bin_low_pc, sym_low_pc);

credit = overlap * time /hist_scale; // time = sample[i], hist_scale = pc_scale.

1.5 小结

Gprof是GUN 工具链中自带的profiler，无需安装成本，与gcc的结合让其使用方便，能够快速上手。但是gprof也有其一定的缺陷，

1、它的测试结果并不能保证完全准确： 它无法统计程序耗在IO以及swap上的时间：

而且，由于其通过采集sample来计算profile的方式，本身就存在一定的失真：

2. gprof不能支持动态库的解析。原因在本文中已经分析。

3. gprof不易维护和扩展，因为gprof的代码是封装在GNU工具链的glibc以及binutils中，修改libc的风险较大，而且版本也不易维护（不同系统中使用的libc版本不一致，如果单独更新glibc，会出现程序crash）。

二、 GooglePerformance Tools

Goolgleperformance tools是google公司开发的一套用于C++Profile的工具集。其中包括：

一个优化的内存管理算法—tcmalloc性能优于malloc。

一个用于CPU profile的工具，用于检测程序的性能热点，这个功能和gprof类似。

一个用于堆检查工具，用于检测程序在是够有内存泄露，这个功能和valgrind类似。

一个用于Heap profile的工具，用于监控程序在执行过程的内存使用情况。

官方文档：

http://code.google.com/p/google-perftools/wiki/GooglePerformanceTools

它的使用方式比较简单：首先在编译程序的时候加上相应的链接库，然后在运行程序时

通过设置相应的环境变量来激活工具。

1.使用其提供的内存管理函数---TC Malloc:

gcc [...] -ltcmalloc

2.使用其堆内存检查工具:

gcc [...] -o myprogram -ltcmalloc

HEAPCHECK=normal ./myprogram

3.使用Heap Profiler:

gcc [...] -o myprogram -ltcmalloc

HEAPPROFILE=/tmp/netheap ./myprogram

4.使用Cpu Profiler:

gcc [...] -o myprogram -lprofiler

CPUPROFILE=/tmp/profile ./myprogram

它的输出也很清晰,下图是一个CpuProfiler的结果图，其中每个方块代码一个函数，方块间的箭头描述了函数之间的调用关系，每个方块里面有两个数字：X ofY，其中Y表示在程序执行过程中函数所消耗的总体时间，X表示函数自身所消耗的时间，所以Y-X及时函数所调用的子函数消耗时间。如果函数没有子函数，则只显示总体时间。（X，Y的单位得sample，每个sample所代表的时间可以设置，默认为10ms）

2.1 安装

a) 安装libunwind

libunwind是一个用于解析程序调用栈的C++库，由于glibc内建的栈回滚功能在64位系统上有bug，因此googleperformance tools建议使用libunwind

下载libunwind-0.99-beta.tar.gz

cd $HOME

tarxzvf libunwind-0.99-beta.tar.gz

mkdir libunwind-0.99-beta-build

cd libunwind-0.99-beta

./configure –prefix=$HOME/libunwind-0.99-beta-build

b) 安装Google PerformanceTools

注意：如果在系统目录中找不到libunwind，google performance tools将默认使用glibc的内建功能，因此我们需要手动设置libunwind的安装目录。

下载google-perftools-1.6.tar.gz

cd $HOME

tar xzvf google-perftools-1.6.tar.gz

mkdir google-perftools-1.6-build

cd google-perftools-1.6

./configure –prefix=$HOME/ google-perftools-1.6-build

CPPFLAGS=-I$HOME/libunwind-0.99-beta-build/include

LDFLAGS=-L$HOME/libunwind-0.99-beta-build/lib

make && make install

2.2 用法

参考官方文档。

这里有两点想突出介绍下，一个是对动态库的支持，一个对动态profiler功能的支持。

2.2.1 动态库的支持

在第一章节里面我们已经证明和分析GUNProfiler不提供对动态库的支持，虽然可以通过修改glibc的代码来扩展此功能，但是维护成本较大。而Goolgle performancetools本身就已经提供了对动态库的支持功能。当然动态库的使用也分两种情况：一种是在运行时动态链接库，一种是在运行时动态加载库。

运行时链接可以动态地将程序和共享库链接并让 Linux 在执行时加载库（如果它已经在内存中了，则无需再加载）。以一个具体例子来说明：

libtestprofiler.cpp只定义了一个耗时计算函数，便于分析。

将libtestprofiler.cpp编译为动态库：

g++--shared -fPIC -g -O0 -o libtestprofiler.so libtestprofiler.cpp

在主程序中调用动态库：

编译主程序，并动态链接libtestprofiler.so：

a) 首先采用GUN Profile的方式编译主程序

g++ -g -O0 -omain main.cpp -ltestprofiler -L. –pg

./main

gprof –b ./main结果如下：

和预想一样，GNU Profile 不能解析动态库的性能热点。

b) 再以google CPU Profile的方式编译主程序：

g++ -g -O0 -omain main.cpp -ltestprofiler -L. -lprofiler-L/home/wul/google-perftools-1.6-build/lib

CPUPROFILE=perf.out./main

pprof --text./main ./perf.out，结果如下：

由此证明，Google CPU Profiler支持对动态链接库的性能分析。

运行时加载允许程序可以有选择地调用库中的函数。使用动态加载过程，程序可以先加载一个特定的库（已加载则不必），然后调用该库中的某一特定函数，这是构建支持插件的应用程序的一个普遍的方法。

还是以上述程序为例，对主程序代码进修改：

编译：

g++ -g -O0 -o main_dl main_dl.cpp -lprofiler -L/home/wul/google-perftools-1.6-build/lib-ldl

CPUPROFILE=perf_dl.out./main_dl

pprof--text ./main_dl ./perf_dl.out，结果如下：

很奇怪，这个结果显示libtestprofiler.so库中的符号没有正确解析，perf_dl.out文件也没有包含libtestprofiler.so的内存映射信息，但是我们确实在主程序已经通过dlopen将动态库装载到内存并执行成功了，为何在主程序的内存映射表中找不到动态库的信息呢？经过一番分析和调查，终于找到原因，因为perf_dl.out文件的输出工作是在主程序执行结束之后、系统回收资源的时候调用的（具体见实现原理一节），而在此时主程序执行了dlclose()函数卸载了libtestprofiler.so，所以随后dump出的内存映射表当然就不会包含libtestprofiler.so的信息了。我们测试下将dlclose(dl_handle)注释后的运行结果：

哈哈，动态库中的符号又能正常解析了。

2.2.2 动态profiler功能

这里首先需要解释下何谓动态profiler功能：传统的profiler工具，以GUNProfiler为例，只能编译阶段控制profiler的开关（-fprofile-arcs-ftest-coverage），但是我们有时候需要在程序的运行阶段，或者说运行的中间阶段控制profiler的开关。Googleperformance tools可以通过CPUPROFILE环境变量在程序运行初阶段控制cpuprofiler的开关，而且根据文档/usr/doc/google-perftools-1.5/pprof_remote_servers.html的提示，可以通过功能扩展可以实现在运行中间阶段或通过http协议远程控制profiler信息的功能。gperftools-httpd项目就已经初步完成了这个功能，我们可以体验一下。

1．从http://code.google.com/p/gperftools-httpd/下载gperftools-httpd安装。

2．修改下测试程序 main.cpp, 正常运行时间，方便测试

这个程序主要做了两点修改，调用ghttpd()启动一个轻量级web servive，已完成pprof的远程请求服务；通过while循环加长了程序的执行时间，已方便验证动态profiler功能。

3．编译，需要连接libghttpd.so、libprofiler.so

g++-g -O0 -o main main.cpp-I/home/wul/gperftools-httpd-0.2-ltestprofiler -L.-L/home/wul/gperftools-httpd-0.2/ -lghttpd -lprofiler -L/home/wul/google-perftools-1.6-build/lib-dl -lpthread

4. 启动测试程序

./main 注意我们这时并没有设置CPUPROFILE环境变量，即表示此时CPU PROFILE功能还没有打开。

5．通过pprof工具远程打开测试程序的CPU profile功能：

pprof ./main http://localhost:9999/pprof/profile，结果如下：

从结果中可以看出，当pprof向本地web服务http://localhost:9999/发送Getpprof/profile请求时，测试程序就会自动开启profile功能，默认的监控时间段是now~now+30s（时间长短可以通过seconds参数设置），等待30s之后，测试程序停止profile，将结果返回给pprof并保存在/home/wul/pprof/main.1292168091.localhost中，此时再通过text命令就可以看到解析后的输出了。pprof工具还支持其它的query参数，譬如采样频率控制、触发采样事件等，具体可以参考gperftools-httpd以及google performancetools的官方文档。

2.3 实现原理

Google performance tools包含四大功能，但是本章主要集中介绍CPU profiler功能，以便和GNU profiler做横向对比。

2.3.1 CPU Profile

googleCPU profile的实现方式不同于gprof，但是两个的实现原理有点相似。CPUprofiler是通过设置SIGPROF信号处理函数来采集sample的，这点和gprof一样，但是CPUprofiler没有在函数入口插入代码，而是通过保存调用栈信息来记录函数的调用图和调用次数。CPUprofiler的主要实现代码在src/profiler.cc中。这个文件中定义了一个CpuProfiler类，并声明一个该类的静态实例。这样在main函数之前，此静态实例就会被初始化。

该构造函数首先会判断系统变量CPUPROFILE是否被设置，如果设置了，则启动CPU profiler进程，否则，直接返回。我们在看看Start函数做了什么：

此函数首先会调用ProfileHandlerGetState来获取其它的控制参数，包括CPUPROFILE_REALTIME和CPUPROFILE_FREQUENCY。

其次，函数调用ProfileData::Start为记录profiler信息分配内存并初始化，其定义在profiledata.cc中。

其中slot数组evict_就是profiler输出文件中的保存内容，具体可参考profiler输出文件的格式说明。Bucket数组hash_是用于临时保存程序调用栈信息的hash表，num_evicted记录evict_数组中的有效长度。这些变量在后续将会经常出现。回到profiler.cc中的CpuProfiler::Start函数，其最后一步调用的是EnableHandler()， 用于设置SIGPROF的信号处理函数。

函数通过ProfileHandlerRegisterCallback注册了一个回调函数prof_handler：

紧接着通过ProfileHandler::EnableHandler注册SIGPROF信号处理函数SignalHandler。

到此，CPU profile的初始化工作基本上都完成了，总结一下主要是完成了两个工作：一个是内存的分配以及初始化，一个是注册SIGPROF信号处理函数，以便采集sample信息。所以接下来的重点将是分析CPU profile是如何采集sample的。首先看看SignalHandler函数的定义：

从代码中可以看出，SignalHandler除了记录中断次数之外，遍历调用了callbacks_链中的所有回调函数，回溯CPU Profile前面的初始化工作，这里就会调用prof_handler函数：

从代码的注解片段中可以理解此函数的主要工作就是记录将当前程序的调用栈信息。顾名思义，GetPC函数用于获取当前pc指针，它是利用linux系统的信号处理机制来获取当前pc的（具体可参考《unix环境高级编程》）， 其主要实现代码在getpc.h中：

GetStackTraceWithContext函数完成了cpu profiler过程中最重要的一步，它最终调用了libunwind库，dump出了当前的函数调用栈信息，其主要实现代码在stacktrace_libunwind-inl.h中：

这个函数的过程有点复杂，它的主要功能是回滚当前调用栈，并将栈指针都保存在stack数组中，根据这些信息就可以记录程序指令的执行次数，以及描述函数之间的调用关系图。（具体实现原理请参考libunwind官网说明）。再对到prof_handler函数中，程序的最后一步就是将当前获取的调用栈信息保存到预先分配的内存中，其具体实现在profiledata.cc文件中：

此函数的处理流程如下:

1．对stack数组的所有项做hash，得到一个hash值；

2．根据hash值在hash_表中查找此调用栈，如果找到匹配项则增加该项的执行次数；

3．如果没有找到则将从相应的hash槽中pop出执行次数最少的一个调用栈，将此调用栈中的所有栈指针值按顺序保存到evict_数组中，并将新调用栈push到hash槽中。

到此，CPU profile的主要流程都走完了，总结一下其一直在循环执行一个动作：定期保存程序的当前调用栈信息。在被测程序执行结束之后，CPU profile所做的最后一步工作就是将evict_数组中保存的数据输出到%CPUPROFILER环境变量制定的文件中（profiledata.cc）：

在dump出evict_数组数据之后，函数还通过DumpProcSelfMaps将/prof/self/map中的信息追加到输出文件中，这些信息记录了应用程序的内存映射情况，是pprof工具解析指令符号的重要依据。（关于/prof/self/map中的信息说明可以参考《程序员的自我修养》）

虽然监控程序已经停止，但是CPUprofiler的工作还没完全结束，因为之前保存在$CPUPROFILER文件中的数据都是二进制格式的，不具备可读性，需要借助pprof工具的解析功能才能揭露它的真实信息。

pprof是用perl语言编写的解析工具，它的主要功能就是将CPU profile的输出数据转换成容易阅读理解的可视格式，如text、pdf、gif等，接下来本文将讲解pprof的主要工作原理，具体细节可以参考pprof代码。

$CPUPROFILER文件中保存了两部分信息：前部分是定期dump的调用栈信息，每个调用栈信息中都包含了执行次数、栈深度以及栈指针值（即指令地址）；后半部分记录应用程序的内存映射图。所以第一步，pprof根据内存映射图和程序符号表将调用栈中的指令地址翻译成容易理解的程序代码；第二步，pprof根据第一部分保存的栈信息描述出程序中的函数调用图；最后一步，pprof根据栈执行次数计算出每段代码的执行次数，再根据定时器的执行频率估算出程序段的执行时间，进而找出程序的性能热点。

2.4 小结

Google performance tools采用了和GUNProfiler近似的原理、不同的方式来达到profiler的效果。由于其通过记录调用栈信息来反推程序段的执行次数，不可避免地会出现遗漏和误算情况，而且和GUNProfiler一样，它也是通过sample的采样频率来估算程序段的运行时间，因此最终计算结果并不是十分精确的，具有一定的误差。但是，Google performance tools较之其他Profiler工具而言，有其自身的特点和优势，Googleperformance tools是一个用户态程序，不需要内核提供支持（对比oprofiler）；它对被监控程序的入侵程序度较小（对比GUNProfiler），无需修改程序代码，以attach的方式跟踪程序执行状态；而且它也是google的开源项目之一，工程量较小，方面后期扩展和二次开发。

三、 C++ Profiler工具特性对比

总结前两章的调研结果，对目前常用的C++ profiler工具做了一个简单的对比，对比的焦点主要集中在日常使用中大家所发现或比较关注的问题。不过由于时间关系，所选工具和对比项都十分有限，希望能在后期的进一步工作中完善补充。

未完待续……

Gprof 简介:

Gprof功能：打印出程序运行中各个函数消耗的时间，可以帮助程序员找出众多函数中耗时最多的函数。产生程序运行时候的函数调用关系，包括调用次数，可以帮助程序员分析程序的运行流程。

有了函数的调用关系，这会让开发人员大大提高工作效率，不用费心地去一点点找出程序的运行流程，这对小程序来说可能效果不是很明显，但对于有几万，几十万代码量的工程来说，效率是毋庸置疑的！而且这个功能对于维护旧代码或者是分析Open Source来说那是相当诱人的，有了调用图，对程序的运行框架也就有了一个大体了解，知道了程序的“骨架“，分析它也就不会再那么茫然，尤其是对自己不熟悉的代码和Open Source。费话不多说了，让我们开始我们的分析之旅吧！

Gprof 实现原理：

通过在编译和链接你的程序的时候（使用 -pg 编译和链接选项），gcc 在你应用程序的每个函数中都加入了一个名为mcount ( or “_mcount” , or “__mcount” , 依赖于编译器或操作系统)的函数，也就是说你的应用程序里的每一个函数都会调用mcount, 而mcount 会在内存中保存一张函数调用图，并通过函数调用堆栈的形式查找子函数和父函数的地址。这张调用图也保存了所有与函数相关的调用时间，调用次数等等的所有信息。

Gprof基本用法：

1． 使用 -pg 编译和链接你的应用程序。

2． 执行你的应用程序使之生成供gprof 分析的数据。

3． 使用gprof 程序分析你的应用程序生成的数据。

Gprof 简单使用：

让我们简单的举个例子来看看Gprof是如何使用的。

1．打开linux终端。新建一个test.c文件，并生用-pg 编译和链接该文件。 test.c 文件内容如下：

#include "stdio.h"

#include "stdlib.h"

void a(){

  printf("\t\t+---call a() function\n");

}

void c(){

  printf("\t\t+---call c() function\n");

}

int b(){

printf("\t+--- call b() function\n");

a();

c();

return 0;

}

命令行里面输入下面命令，没加-c选项，gcc 会默认进行编译并链接生成a.out：

[linux /home/test]$gcc -pg test.c

如果没有编译错误，gcc会在当前目录下生成一个a.out文件，当然你也可以使用 –o 选项给生成的文件起一个别的名字，像 gcc –pg test.c –o test , 则gcc会生成一个名为test的可执行文件,在命令行下输入[linux /home/test]$./test , 就可以执行该程序了，记住一定要加上 ./ 否则程序看上去可能是执行，可是什么输出都没有。

2．执行你的应用程序使之生成供gprof 分析的数据。 命令行里面输入:

[linux /home/test]$a.out

main() function()

+--- call b() function

+---call a() function

+---call c() function

[linux /home/test]$

你会在当前目录下看到一个gmon.out 文件， 这个文件就是供gprof 分析使用的。

3．使用gprof 程序分析你的应用程序生成的数据。

命令行里面输入:

[linux /home/test]$ gprof -b a.out gmon.out | less

由于gprof输出的信息比较多，这里使用了 less 命令，该命令可以让我们通过上下方向建查看gprof产生的输出，| 表示gprof -b a.out gmon.out 的输出作为 less的输入。下面是我从gprof输出中摘抄出的与我们有关的一些详细信息。

从上面的输出我们能明显的看出来，main 调用了 b 函数， 而b 函数分别调用了a 和 c 函数。由于我们的函数只是简单的输出了一个字串，故每个函数的消耗时间都是0 秒。

gprof产生的信息解释如下:

gprof产生的信息解释

常用的Gprof 命令选项解释：

-b不再输出统计图表中每个字段的详细描述。

-p 只输出函数的调用图（Call graph 的那部分信息）。

-q 只输出函数的时间消耗列表。

-E Name不再输出函数Name 及其子函数的调用图，此标志类似于 -e 标志，但它在总时间和百分比时间的计算中排除了由函数Name 及其子函数所用的时间。

-e Name 不再输出函数Name 及其子函数的调用图（除非它们有未被限制的其它父函数）。可以给定多个 -e 标志。一个 -e 标志只能指定一个函数。

-F Name 输出函数Name 及其子函数的调用图，它类似于 -f 标志，但它在总时间和百分比时间计算中仅使用所打印的例程的时间。可以指定多个 -F 标志。一个 -F 标志只能指定一个函数。-F 标志覆盖 -E 标志。

-f Name输出函数Name 及其子函数的调用图。可以指定多个 -f 标志。一个 -f 标志只能指定一个函数。

-z 显示使用次数为零的例程（按照调用计数和累积时间计算）。

到这为止你可能对gprof 有了一个比较感性的认识了，你可能会问如何用它去分析一个真正的Open Source 呢！下面就让我们去用gprof去分析一个Open Source，看看如何去在真实的环境中使用它。

使用Gprof 分析 Cflow开源项目

CFlow 是程序流程分析工具，该工具可以通过分析C源代码，产生程序调用图！有点跟Gprof差不多，不过CFlow是通过源代码进行的静态分析并且 不能分析C++ 程序,你可以到http://www.gnu.org/software/cflow/去下载源代码。

假设你已经下载了该源代码（cflow-1.1.tar.gz）,并把它放置在/home目录下，让我们看看如何在这个应用上使用gprof。

1． 使用 -pg 编译和链接该应用程序,请输入下列命令。

  [linux /home/]tar zxvf cflow-1.1.tar.gz

[linux /home/cflow-1.1/src]$./configure

[linux /home]$make CFLAGS=-pg LDFLAGS=-pg 

如果没有出错你会在/home/cflow-1.1/src 目录下发行一个名为cflow的可执行文件，这就是我们加入-pg编译选项后编译出来的可以产生供gprof提取信息的可执行文件。记住一定要在编译和链接的时候都使用-pg选项，否则可能不会产生gmon.out文件。对于cflow项目，CFLAGS=-pg 是设置它的编译选项，LDFLAGS=-pg是设置它的链接选项。当然你也可以直接修改它的Makefile来达到上述相同的目的，不过一定要记住编译和链接都要使用-pg选项。

2． 运行cflow 程序使之生成gmon.out 文件供gprof使用。

[linux /home/cflow-1.1/src]$cflow parser.c

查看/home/cflow-1.1/src目录下有没有产生gmon.out文件，如果没有请重复第一步，并确认你已经在编译和链接程序的时候使用了-pg 选项。Cflow的使用请参考http://www.gnu.org/software/cflow/manual/cflow.html。

3． 使用gprof分析程序

[linux /home/cflow-1.1/src]$gprof -b cflow gmon.out | less

恭喜你，不出意外你会在屏幕上看到gprof的输出，函数消耗时间和函数调用图，下面是我从我的输出中摘抄出来的一小段。

通过分析％time你就知道了那个函数消耗的时间最多，你可以根据这个输出信息做有目的的优化，不过cflow执行的速度是在是太快了，以至％time都是0 (消耗时间是以秒为单位进行统计的)。

生成图形化的函数调用图

1．Graphviz 工具

看到这里你也可能觉得上面的函数调用图实在是不方便察看，也看不出来一个程序调用的整体框架。没有关系，我再介绍一个有用的工具给你，使用 Graphviz，Graphviz or Graph Visualization 是由 AT&T 开发的一个开源的图形可视化工具。它提供了多种画图能力，但是我们重点关注的是它使用 Dot 语言直连图的能力。在这里，将简单介绍如何使用 Dot 来创建一个图形，并展示如何将分析数据转换成 Graphviz 可以使用的规范, Dot 使用的图形规范。

使用 Dot 语言，你可以指定三种对象：图、节点和边。为了让你理解这些对象的含义，我将构建一个例子来展示这些元素的用法。

下图给出了一个简单的定向图（directed graph），其中包含 3 个节点。第一行声明这个图为 G，并且声明了该图的类型（digraph）。接下来的三行代码用于创建该图的节点，这些节点分别名为 node1、node2 和 node3。节点是在它们的名字出现在图规范中时创建的。边是在在两个节点使用边操作（->）连接在一起时创建的，如第 6 行到第 8 行所示。我还对边使用了一个可选的属性 label，用它来表示边在图中的名称。最后，在第 9 行完成对该图规范的定义。

使用 Dot 符号表示的示例图（test.dot）

 1： digraph G {

2：   node1;

3：   node2;

4：   node3;

5：

6：   node1 -> node2 [label="edge_1_2"];

7：   node1 -> node3 [label="edge_1_3"];

8：   node2 -> node3 [label="edge_2_3"];

9： }

要将这个 .dot 文件转换成一个图形映像，则需要使用 Dot 工具，这个工具是在 Graphviz 包中提供的。清单 6 介绍了这种转换。

清单 6. 使用 Dot 来创建 JPG 映像

[linux /home]$ dot -Tjpg test.dot -o test.jpg

在这段代码中，我告诉 Dot 使用 test.dot 图形规范，并生成一个 JPG 图像，将其保存在文件 test.jpg 中。所生成的图像如图1所示。在此处，我使用了 JPG 格式，但是 Dot 工具也可以支持其他格式，其中包括 GIF、PNG 和 postscript等等。

 

图 1. Dot 创建的示例图

Dot 语言还可以支持其他一些选项，包括外形、颜色和很多属性。有兴趣可以查看graphviz相关文档。

2．从gprof的输出中提取调用图信息，产生可供Graphviz使用的dot文件。

这样的脚本有人已经实现了，我们只要下载一个现成的就可以了，首先从http://www.ioplex.com/~miallen/ 网站下载一个mkgraph脚本。解压该脚本到包含gmon.out文件的目录下。使用mkgraph0.sh产生调用的jpg图像文件。例如：使用上面的例子，生成cflow的调用图。

[linux /home/cflow-1.1/src]$ mkgraph0.sh cflow gmon.out

部分调用图如下，有了这个图是不是对程序整体框架有了个清晰地了解，如果你对生成的调用图效果不满意，你还可以通过修改mkgraph0脚本使之产生合适的dot文件即可：

部分调用图如下

总结：

使用gprof , Graphviz , mkgraph 生成函数调用图

1． 使用 -pg 编译和链接你的应用程序。

2． 执行你的应用程序使之生成供gprof 分析的数据。

3． 使用mkgraph脚本生成图形化的函数调用图。

相关资料：

文档：用 Graphviz 可视化函数调用

文档：Speed your code with the GNU profiler

文档：gropf 帮助文件

Mkgraph 脚本：http://www.ioplex.com/~miallen/

Graphviz 工具：http://www.graphviz.org

Cflow ：http://www.gnu.org/software/cflow/

linux环境下 C++性能测试工具 gprof 和gprof2dot

一. 概要
1. Gprof 是在运行中收集程序的统计信息。
程序的运行方式会严重影响统计的信息结果。因为不同的执行路径下，程序的行为方式会有很大的差别。

2. Gprof 使用步骤
(1) 编译链接程序的时候，使能Gprof
(2) 执行程序生成profile data file
(3) 使用Gprof分析profile data

3. 输出格式
(1) flat profile
每一个函数花费了多少时间，每一个函数被调用了多少次
(2) call graph
对每一个函数来说，哪个函数调用了它，多少次；它调用了哪些个函数，多少次
这个函数花费了多少时间，它调用的函数花费了多少时间
(3) annotated source
生成一份源代码的拷贝，标注出每一个block被执行了多少次

二. 为 Gprof 编译程序
1. 给GNU Tools 传递PG选项
gcc -g -pg .............
编译器和连接器都需要加上-pg 选项
2. 执行程序
程序执行结束后，会生成gmon.out 统计文件，这个就是profiler data file。
注意：只有在程序正常终止的时候，才会生成这个文件。也就是说，程序必须是从exit或者return终止的。
3. 分析生成结果
gprof [Options] <可执行文件> <profiler data file>

三. Gprof 的输出格式
G平日哦方可生成四种格式的统计结果，其中的line-by-line的输出，已经转移到gconv工具上。
所以目前的Gprof主要是三种格式的输出。

1. Flat Profile：

 

2. Call Graph
granularity: each sample hit covers 2 byte(s) for 20.00% of 0.05 seconds

index % time self children called name
<spontaneous>
[1] 100.0 0.00 0.05 start [1]
0.00 0.05 1/1 main [2]
0.00 0.00 1/2 on_exit [28]
0.00 0.00 1/1 exit [59]
-----------------------------------------------
0.00 0.05 1/1 start [1]
[2] 100.0 0.00 0.05 1 main [2]
0.00 0.05 1/1 report [3]
-----------------------------------------------
0.00 0.05 1/1 main [2]
[3] 100.0 0.00 0.05 1 report [3]
0.00 0.03 8/8 timelocal [6]
0.00 0.01 1/1 print [9]
0.00 0.01 9/9 fgets [12]
0.00 0.00 12/34 strncmp <cycle 1> [40]
0.00 0.00 8/8 lookup [20]
0.00 0.00 1/1 fopen [21]
0.00 0.00 8/8 chewtime [24]
0.00 0.00 8/16 skipspace [44]
-----------------------------------------------
[4] 59.8 0.01 0.02 8+472 <cycle 2 as a whole> [4]
0.01 0.02 244+260 offtime <cycle 2> [7]
0.00 0.00 236+1 tzset <cycle 2> [26]
-----------------------------------------------


虚线分割的每一个部分叫做一个entity，用来描述一个函数或者一个cycle。
其中每一个以 [数字] 开始的行叫做 primary line，这个entity主要就是描述它的。
在 primary line 之前的行显示的是调用这个函数的函数，也就是caller。在它之后
的是这个函数调用的函数，也就是subroutine。

2.1 Primary Line

index % time self children called name
...
[3] 100.0 0.00 0.05 1 report [3]

+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 

2.2 Lines for a function's caller

index % time self children called name
...
0.00 0.05 1/1 main [2]
[3] 100.0 0.00 0.05 1 report [3]
 

如果caller不能确定，就会出现<spontaneous>作为caller。

http://www.ezdoum.com/stories.php?story=07/10/10/5189338

1. 重新编译glib

CFLAGS="-pg -g" ./autogen.sh --disable-gtk-doc --enable-debug=minimum \
     --prefix=/your install path --disable-shared

make; make install

2. 写个测试代码

#define REPEATS 100000

#include <glib.h>
#include <glib-object.h>

/*************************/

#define TYPE_TEST_OBJECT    (test_object_get_type ())
#define TEST_OBJECT(obj)    (G_TYPE_CHECK_INSTANCE_CAST ((obj), \
                             TYPE_TEST_OBJECT, TestObject))
#define IS_TEST_OBJECT(obj) (G_TYPE_CHECK_INSTANCE_TYPE ((obj), \
                             TYPE_TEST_OBJECT))

typedef struct _TestObject       TestObject;
typedef struct _TestObjectClass  TestObjectClass;

struct _TestObject
{
    GObject    parent_instance;

    gint       foo;
    gchar     *bar;
};

struct _TestObjectClass
{
    GObjectClass parent_class;
};

GType        test_object_get_type     (void) G_GNUC_CONST;
TestObject  *test_object_new          (void);

enum
{
    PROP_0,
    PROP_FOO,
    PROP_BAR
};

static void   test_object_class_init   (TestObjectClass *klass);
static void   test_object_init         (TestObject      *object);
static void   test_object_finalize     (GObject         *object);
static void   test_object_set_property (GObject         *object,
				        guint            property_id,
					const GValue    *value,
					GParamSpec      *pspec);
static void   test_object_get_property (GObject         *object,
                                        guint            property_id,
                                        GValue          *value,
                                        GParamSpec      *pspec);


static GObjectClass *parent_class = NULL;


GType
test_object_get_type (void)
{
  static GType test_object_type = 0;

  if (!test_object_type)
    {
      static const GTypeInfo test_object_info =
      {
        sizeof (TestObjectClass),
	(GBaseInitFunc) NULL,
	(GBaseFinalizeFunc) NULL,
	(GClassInitFunc) test_object_class_init,
	NULL,		/* class_finalize */
	NULL,		/* class_data     */
	sizeof (TestObject),
	0,              /* n_preallocs    */
	(GInstanceInitFunc) test_object_init,
      };

      test_object_type =
	g_type_register_static (G_TYPE_OBJECT, "TestObject",
				&test_object_info, 0);
    }

  return test_object_type;
}


static void
test_object_class_init (TestObjectClass *klass)
{
  GObjectClass *object_class;
  GParamSpec   *param_spec;

  object_class = G_OBJECT_CLASS (klass);
  parent_class = g_type_class_peek_parent (klass);

  object_class->set_property = test_object_set_property;
  object_class->get_property = test_object_get_property;

  param_spec = g_param_spec_string ("bar", NULL, NULL,
				    NULL,
				    G_PARAM_READABLE | G_PARAM_WRITABLE
#ifdef MAKE_IT_SLOW_2
                                    | G_PARAM_CONSTRUCT_ONLY
#endif
                                    );
  g_object_class_install_property (object_class, PROP_BAR, param_spec);

  param_spec = g_param_spec_int ("foo", NULL, NULL,
				 G_MININT, G_MAXINT, 0,
				 G_PARAM_READABLE | G_PARAM_WRITABLE
#ifdef MAKE_IT_SLOW_2
                                    | G_PARAM_CONSTRUCT_ONLY
#endif
                                 );
  g_object_class_install_property (object_class, PROP_FOO, param_spec);

  object_class->finalize = test_object_finalize;
}

static void
test_object_init (TestObject *object)
{
  object->bar = NULL;
  object->foo = 0;
}

static void
test_object_finalize (GObject *object)
{
  TestObject *obj;

  obj = (TestObject *) (object);

  g_free (obj->bar);

  if (G_OBJECT_CLASS (parent_class)->finalize)
    G_OBJECT_CLASS (parent_class)->finalize (object);
}

static void
test_object_set_property (GObject      *object,
			  guint         property_id,
			  const GValue *value,
			  GParamSpec   *pspec)
{
  TestObject *test_object;

  test_object = TEST_OBJECT (object);

  switch (property_id)
    {
    case PROP_FOO:
      test_object->foo = g_value_get_int (value);
      break;

    case PROP_BAR:
      g_free (test_object->bar);
      test_object->bar = g_value_dup_string (value);
      break;

    default:
      G_OBJECT_WARN_INVALID_PROPERTY_ID (object, property_id, pspec);
      break;
    }
}

static void
test_object_get_property (GObject     *object,
			  guint        property_id,
			  GValue      *value,
			  GParamSpec  *pspec)
{
  TestObject *test_object;

  test_object = TEST_OBJECT (object);

  switch (property_id)
    {
    case PROP_BAR:
      g_value_set_string (value, test_object->bar);
      break;

    case PROP_FOO:
      g_value_set_int (value, test_object->foo);
      break;

    default:
      G_OBJECT_WARN_INVALID_PROPERTY_ID (object, property_id, pspec);
      break;
    }
}


TestObject *
test_object_new (void)
{
#ifdef MAKE_IT_SLOW_1
  return TEST_OBJECT (g_object_new (test_object_get_type (),
                                    "foo", 5,
                                    "bar", "blah",
                                    NULL));
#else
  TestObject *obj =
    TEST_OBJECT (g_object_new (test_object_get_type (),
                               NULL));
  obj->foo = 5;
  obj->bar = g_strdup ("blah");
  return obj;
#endif
}


/*************************/


int main (int argc, char *argv[])
{
  GTimeVal start, end;
  int i;
  TestObject *obj[REPEATS];

  g_type_init_with_debug_flags (G_TYPE_DEBUG_NONE);

  test_object_new ();

  g_get_current_time (&start);
  for (i = 0; i < REPEATS; i++)
    obj[i] = test_object_new ();
  g_get_current_time (&end);

  if (end.tv_usec - start.tv_usec < 0)
    end.tv_sec--, end.tv_usec += 1000000;
  g_print ("loop %d, %ld.%06ld sec\n", REPEATS,
           (end.tv_sec - start.tv_sec),
           (end.tv_usec - start.tv_usec));
  return 0;
}

3. 编译测试代码

Then try:
  gcc -Wall -pg -g gobject-test.c -o gobject-test \
    `pkg-config --cflags --libs gobject-2.0` 
vs.
  gcc -DMAKE_IT_SLOW_1 -Wall -pg -g gobject-test.c -o gobject-test \
    `pkg-config --cflags gobject-2.0` `pkg-config --libs gobject-2.0`
or
  gcc -DMAKE_IT_SLOW_2 -Wall -pg -g gobject-test.c -o gobject-test \
    `pkg-config --cflags gobject-2.0` `pkg-config --libs gobject-2.0`

4. 用gprof看看：

gprof -b  ./gobject-test
Flat profile:

Each sample counts as 0.01 seconds.
 no time accumulated

  %   cumulative   self              self     total           
 time   seconds   seconds    calls  Ts/call  Ts/call  name    
  0.00      0.00     0.00   200002     0.00     0.00  test_object_get_type
  0.00      0.00     0.00   100001     0.00     0.00  test_object_new


			Call graph


granularity: each sample hit covers 2 byte(s) no time propagated

index % time    self  children    called     name
                0.00    0.00  200002/200002      test_object_new [2]
[1]      0.0    0.00    0.00  200002         test_object_get_type [1]
-----------------------------------------------
                0.00    0.00  100001/100001      main [8]
[2]      0.0    0.00    0.00  100001         test_object_new [2]
                0.00    0.00  200002/200002      test_object_get_type [1]
-----------------------------------------------


Index by function name

   [1] test_object_get_type    [2] test_object_new

build again:

gcc -DMAKE_IT_SLOW_1 -Wall -pg -g gobject-test.c -o gobject-test `pkg-config --cflags --libs gobject-2.0`

gprof -b  ./gobject-test
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ns/call  ns/call  name    
 50.12      0.01     0.01   400004    12.53    12.53  test_object_get_type
 50.12      0.01     0.01                             frame_dummy
  0.00      0.01     0.00   100001     0.00    25.06  test_object_new


			Call graph


granularity: each sample hit covers 2 byte(s) for 99.77% of 0.01 seconds

index % time    self  children    called     name
                0.00    0.00  200002/400004      test_object_set_property [5]
                0.00    0.00  200002/400004      test_object_new [3]
[1]     50.0    0.01    0.00  400004         test_object_get_type [1]
-----------------------------------------------
                                                 <spontaneous>
[2]     50.0    0.01    0.00                 frame_dummy [2]
-----------------------------------------------
                0.00    0.00  100001/100001      main [4]
[3]     25.0    0.00    0.00  100001         test_object_new [3]
                0.00    0.00  200002/400004      test_object_get_type [1]
-----------------------------------------------
                                                 <spontaneous>
[4]     25.0    0.00    0.00                 main [4]
                0.00    0.00  100001/100001      test_object_new [3]
-----------------------------------------------
                                                 <spontaneous>
[5]     25.0    0.00    0.00                 test_object_set_property [5]
                0.00    0.00  200002/400004      test_object_get_type [1]
-----------------------------------------------


Index by function name

   [2] frame_dummy             [1] test_object_get_type    [3] test_object_new

build again:

gcc -DMAKE_IT_SLOW_2 -Wall -pg -g gobject-test.c -o gobject-test `pkg-config --cflags --libs gobject-2.0`

gprof -b  ./gobject-test
Flat profile:

Each sample counts as 0.01 seconds.
 no time accumulated

  %   cumulative   self              self     total           
 time   seconds   seconds    calls  Ts/call  Ts/call  name    
  0.00      0.00     0.00   400004     0.00     0.00  test_object_get_type
  0.00      0.00     0.00   100001     0.00     0.00  test_object_new


			Call graph


granularity: each sample hit covers 2 byte(s) no time propagated

index % time    self  children    called     name
                0.00    0.00  200002/400004      test_object_set_property [14]
                0.00    0.00  200002/400004      test_object_new [2]
[1]      0.0    0.00    0.00  400004         test_object_get_type [1]
-----------------------------------------------
                0.00    0.00  100001/100001      main [8]
[2]      0.0    0.00    0.00  100001         test_object_new [2]
                0.00    0.00  200002/400004      test_object_get_type [1]
-----------------------------------------------


Index by function name

   [1] test_object_get_type    [2] test_object_new