本文详细说明用 gprof 来调试 C++ 的相关技巧。
gprof 是 GNU profiler 工具。可以显示程序运行的“flat profile”,包括每个函数的调用次数,每个函数消耗的处理器时间。
也可以显示“调用图” ( call graph ) ,包括函数的调用关系,每个函数调用花费了多少时间。
还可以显示“注释的源代码”,是程序源代码的一个复本,标记有程序中每行代码的执行次数。
基本用法:
1. 使用 -pg 选项编译和链接你的应用程序。
2. 执行你的应用程序,使之运行完成后生成供 gprof 分析的数据文件(默认是gmon.out)。
3. 使用 gprof 程序分析你的应用程序生成的数据,例如:
$ gprof a.out gmon.out > result.txt
举例
gcc -Wall -pg -o test test.c //程序文件名称 test.c 编译时使用 -pg
现在我们可以再次运行生成的可执行文件 test,并使用我们前面使用的测试数据。这次我们运行的时候,test 运行的分析数据会被搜集并保存在 gmon.out 文件中,然后我们可以通过运行 gprof test 来查看结果,整个过程如下:
$ ./test $ gprof test gmon.out > test_result.txt
这样,gprof 的分析结果就会放到文件 test_result.txt 里,我们查阅这个文件就可以得到相关的信息了。
gprof并不神奇,在编译和链接程序的时 候(使用 -pg 编译和链接选项),gcc 在你应用程序的每个函数中都加入了一个名为mcount(or“_mcount”, or“__mcount”)的函数,也就是说-pg编译的应用程序里的每一个函数都会调用mcount, 而mcount会在内存中保存一张函数调用图,并通过函数调用堆栈的形式查找子函数和父函数的地址。这张调用图也保存了所有与函数相关的调用时间,调用次数等等的所有信息。
程序运行结束后,会在程序退出的路径下生成一个 gmon.out文件。这个文件就是记录并保存下来的监控数据。可以通过命令行方式的gprof或图形化的Kprof来解读这些数据并对程序的性能进行分析。
另外,如果想查看库函数的 profiling,需要在编译是再加入“-lc_p”编译参数代替“-lc”编译参数,这样程序会链接libc_p.a 库,才可以产生库函数的profiling信息。如果想执行一行一行的profiling,还需要加入“-g”编译参数。
gprof 产生的信息形式如下:
Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls ms/call ms/call name 33.34 0.02 0.02 7208 0.00 0.00 open 16.67 0.03 0.01 244 0.04 0.12 offtime 16.67 0.04 0.01 8 1.25 1.25 memccpy 16.67 0.05 0.01 7 1.43 1.43 write 16.67 0.06 0.01 mcount 0.00 0.06 0.00 236 0.00 0.00 tzset 0.00 0.06 0.00 192 0.00 0.00 tolower 0.00 0.06 0.00 47 0.00 0.00 strlen 0.00 0.06 0.00 45 0.00 0.00 strchr 0.00 0.06 0.00 1 0.00 50.00 main 0.00 0.06 0.00 1 0.00 0.00 memcpy 0.00 0.06 0.00 1 0.00 10.11 print 0.00 0.06 0.00 1 0.00 0.00 profil 0.00 0.06 0.00 1 0.00 50.00 report ...
其中各列的含义如下:
% the percentage of the total running time of the time program used by this function.
函数使用时间占所有时间的百分比。 cumulative a running sum of the number of seconds accounted seconds for by this function and those listed above it. 函数和上列函数累计执行的时间。 self the number of seconds accounted for by this seconds function alone. This is the major sort for this listing. 函数本身所执行的时间。 calls the number of times this function was invoked, if this function is profiled, else blank. 函数被调用的次数 self the average number of milliseconds spent in this ms/call function per call, if this function is profiled, else blank. 每一次调用花费在函数的时间microseconds。 total the average number of milliseconds spent in this ms/call function and its descendents per call, if this function is profiled, else blank. 每一次调用,花费在函数及其衍生函数的平均时间microseconds。 name the name of the function. This is the minor sort for this listing. The index shows the location of the function in the gprof listing. If the index is in parenthesis it shows where it would appear in the gprof listing if it were to be printed. 函数名
更多详细介绍
1. 在内存中分配一些内存,存储程序执行期间的统计数据 2. 在GCC使用-pg选项编译后,gcc会在程序的入口处(main 函数之前)调用
void monstartup(lowpc, highpc)
在每个函数的入口处调用
void _mcount()
在程序退出时(在 atexit () 里)调用
void _mcleanup()
* monstartup:负责初始化profile环境,分配内存空间 * _mcount: 记录每个函数代码的caller和callee的位置 * _mcleanup:清除profile环境,保存结果数据为gmon.out,供gprof分析结果
3.在_mcount函数中跟踪程序的执行状况,记录程序代码的执行次数,时间等数据。
常用的gprof命令选项: -b 不再输出统计图表中每个字段的详细描述。 -p 只输出函数的调用图(Call graph的那部分信息)。 -q 只输出函数的时间消耗列表。 -e Name 不再输出函数Name 及其子函数的调用图(除非它们有未被限制的其它父函数)。可以给定多个 -e 标志。一个 -e 标志只能指定一个函数。 -E Name 不再输出函数Name 及其子函数的调用图,此标志类似于 -e 标志,但它在总时间和百分比时间的计算中排除了由函数Name 及其子函数所用的时间。 -f Name 输出函数Name 及其子函数的调用图。可以指定多个 -f 标志。一个 -f 标志只能指定一个函数。 -F Name 输出函数Name 及其子函数的调用图,它类似于 -f 标志,但它在总时间和百分比时间计算中仅使用所打印的例程的时间。可以指定多个 -F 标志。一个 -F 标志只能指定一个函数。-F 标志覆盖 -E 标志。 -z 显示使用次数为零的例程(按照调用计数和累积时间计算)。
使用注意: 1) 一般gprof只能查看用户函数信息。如果想查看库函数的信息,需要在编译是再加入“-lc_p”编译参数代替“-lc”编译参数,这样程序会链接libc_p.a库,才可以产生库函数的profiling信息。 2) gprof只能在程序正常结束退出之后才能生成程序测评报告,原因是gprof通过在atexit()里注册了一个函数来产生结果信息,任何非正常退出都不会执行atexit()的动作,所以不会产生gmon.out文件。如果你的程序是一个不会退出的服务程序,那就只有修改代码来达到目的。如果不想改变程序的运行方式,可以添加一个信号处理函数解决问题(这样对代码修改最少),例如:
static void sighandler( int sig_no ) { exit(0); } signal( SIGUSR1, sighandler );
当使用kill -USR1 pid 后,程序退出,生成gmon.out文件。
函数调用图 ( 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]
-----------------------------------------------
函数调用图用 — 线分割成了很多块,每一块以类似 3 这样的索引开头的,这一行下面的所有函数都是被这一行的函数所调用的。
在这一行的上面,有可能会另外一行,这上面的一行表示调用本主函数的父函数。
In each entry, the primary line is the one that starts with an index number in square brackets. The end of this line says which function the entry is for. The preceding lines in the entry describe the callers of this function and the following lines describe its subroutines (also called children when we speak of the call graph).
其中这些关键字的含义:
self
当这个函数被父函数调用的时候,会有一些直接开销,这个就表示这个直接开销的时间消耗量。
children
所有子函数消耗掉的时间。
self 栏和 children 栏消耗的总时间应该等于父函数调用该函数所用的时间。
called
有两个数据,用 / 隔开,类似于 20/22 这样的形式。前面的数据表示该函数被父函数调用的次数,而 / 后面的数字则表示非递归调用该函数的总次数。
name and index number
The name of the caller of report to which this line applies, followed by the caller's index number.
Not all functions have entries in the call graph; some options to gprof request the omission of certain functions. When a caller has no entry of its own, it still has caller-lines in the entries of the functions it calls.
If the caller is part of a recursion cycle, the cycle number is printed between the name and the index number.
If the identity of the callers of a function cannot be determined, a dummy caller-line is printed which has `<spontaneous>' as the "caller's name" and all other fields blank. This can happen for signal handlers.
编辑 其他 C/C++ 程序分析器
还有其他很多分析器可以使用gprof 的数据, 例如KProf (截屏) 和 cgprof。虽然图形界面的看起来更舒服,但我个人认为命令行的gprof 使用更方便。
http://hi.baidu.com/yesbaba/blog/item/016ccc4ba78d23f482025cb6.html
gprof 测试的时间最小值好像是 0.01 ms,所以当你的函数运行得过快,也就是说小于 0.01 ms,也就没有必要改进了。
gprof 只有对大型程序的性能分析上,比较有用。
gprof 只是工具,更多的性能分析只能靠程序员自己。
Valgrind/Callgrind
OProfile
google-perftools
intel vtune,跨平台,收费