Gprof 使用

Gprof 使用

Gprof 使用 2011-10-05 22:43:35

分类： LINUX

 

一. 概要
    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：
   

1. %               the percentage of the total running time of the
2. time            program used by this function.(在整个程序运行时间中，
3.                 这个函数运行时间所占的百分比)
   
4. 
   
5. cumulative      a running sum of the number of seconds accounted
6. seconds         for by this function and those listed above it.
7.                 (这个函数和列在它之前的函数，以秒为单位运行时间的总和)
   
8. 
   
9. self            the number of seconds accounted for by this
10. seconds         function alone. This is the major sort for this
11.                 listing.(这个函数自身运行时间的总和，以秒为单位)
12. 
    
13. calls           the number of times this function was invoked, if
14.                 this function is profiled, else blank.(这个函数
15.                 被调用的总次数)
16. 
    
17. self            the average number of milliseconds spent in this
18. ms/call         function per call, if this function is profiled,
19.                 else blank.(这个函数每次被调用的平均时间，以毫秒为单位)
20. 
    
21. total           the average number of milliseconds spent in this
22. ms/call         function and its descendents per call, if this
23.                 function is profiled, else blank.(这个函数和在它内部调用的
24.                 函数，每次被调用的平均运行时间)
25. 
    
26. name            the name of the function. This is the minor sort
27.                 for this listing. The index shows the location of
28.                 the function in the gprof listing. If the index is
29.                 in parenthesis it shows where it would appear in
30.                 the gprof listing if it were to be printed.

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]

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

1. index
2.     Entries are numbered with consecutive integers. Each function therefore has an index number, which appears at the beginning of its primary line.
3. 
   
4.     Each cross-reference to a function, as a caller or subroutine of another, gives its index number as well as its name. The index number guides you if you wish to look for the entry for that function.
5. 
   
6. % time
   
7.     This is the percentage of the total time that was spent in this function, including time spent in subroutines called from this function.(花费在这个函数中的时间在整个程序全部运行时间中的百分比，其中包括花费在这个函数调用的子函数中的时间)
8. 
   
9.     The time spent in this function is counted again for the callers of this function. Therefore, adding up these percentages is meaningless.(在这个函数的调用函数caller中，这个函数的运行时间，还会被计算在内，所以将这些百分数加在一起没有意义)
10. 
    
11. self
    
12.     This is the total amount of time spent in this function. This should be identical to the number printed in the seconds field for this function in the flat profile.(这个函数自身花费的时间。这个数应该和Flat Profile中的记录一样)
13. 
    
14. children
    
15.     This is the total amount of time spent in the subroutine calls made by this function. This should be equal to the sum of all the self and children entries of the children listed directly below this function. (花费在这个函数调用的所有函数的总时间。这个数应该和列在这个函数下面的子函数的全部 self 和 children之和相等)
16. called This is the number of times the function was called.(这个函数被调用的次数)
17. 
    
18.      If the function called itself recursively, there are two numbers, separated by a `+'. The first number counts non-recursive calls, and the second counts recursive calls.(如果这个函数被循环调用，这里就会有两个被“+”分隔的数字，第一个数字表示非递归调用的次数，第二个表示递归调用的次数)
19. 
    
20. In the example above, the function report was called once from main.
21. 
    
22. name
    
23.     This is the name of the current function. The index number is repeated after it.
24. 
    
25. If the function is part of a cycle of recursion, the cycle number is printed between the function's name and the index number . For example, if function gnurr is part of cycle number one, and has index number twelve, its primary line would be end like this:
26. 
    
27.      gnurr <cycle 1> [12]
28. 如果这个函数是一个循环递归的一部分，循环编号将会打印在函数名和函数索引号之间。例如：如果函数gnurr是循环一的一部分，并且它的索引号是12，它的primary line就应该如下：
29.     gnurr <cycle 1> [12]

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]

1. self
2.     An estimate of the amount of time spent in report itself when it was called from main.
3.     (report自己花费的时间)
4. 
   
5. children
6.     An estimate of the amount of time spent in subroutines of report when report was called from main.
7.     (report的子函数花费的总时间)
8. 
   
9.     The sum of the self and children fields is an estimate of the amount of time spent within calls to
   
10.     report from main.
11. 
    
12. called
13.     Two numbers: the number of times report was called from main, followed by the total number of
    
14.     nonrecursive calls to report from all its callers.(两个数字：第一个，从main函数中调用report的次数，
15.     第二个，report被非递归形式调用的总次数)
16. 
    
17. name and index number
18.     The name of the caller of report to which this line applies, followed by the caller's index number.
19. 
    
20.     Not all functions have entries in the call graph; some options to gprof request the omission of certain
    
21.     functions. When a caller has no entry of its own, it still has caller-lines in the entries of the
    
22.     functions it calls.(不是所有的函数在call graph中都有entity)
23. 
    
24.     If the caller is part of a recursion cycle, the cycle number is printed between the name and the index
    
25.     number.(如果caller是一个递归循环的一部分，循环编号会打印在caller的名字和编号之间)

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

====== to be continue ======

 

调试工具-gprof 2012-04-23 11:23:23

分类： LINUX

 

gprof是linux系统自带的GNU profile工具

提供

1.程序运行的“flat profile”，包括每个函数的调用次数，每个函数消耗的处理器时间。
2.“调用图”，包括函数的调用关系，每个函数调用花费了多少时间。
3.“注释的源代码”，是程序源代码的一个复本，标记有程序中每行代码的执行次数。

用法

1.使用-pg选项编译和链接你的应用程序。
2.执行你的应用程序，使之运行完成后生成供gprof分析的数据文件（默认是gmon.out）。
3.使用gprof程序分析你的应用程序生成的数据，例如：gporf a.out gmon.out。

示例

gcc -Wall -pg -o test test.c 	//程序文件名称 test.c 
编译时使用 -pg

./test 
				//现在可以再次运行test，并使用前面使用的测试数据
				//这次运行时，test运行的分析数据会被搜集并保存在'gmon.out'文件中

gprof test 
			//可以通过运行 ' gprof 
test '来查看结果。

原理

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”编译参数。

缺点

1.调试多线程程序只能统计主线程的信息
2.不能用于调试后台进程
3.只有正常退出时才能产生gmon.out文件

对缺点3.的说明

原因是gprof通过在atexit()里注册了一个函数来产生结果信息，任何非正常退出都不会执行atexit()的动作，所以不会产生gmon.out文件。
如果你的程序是一个不会退出的服务程序，那就只有修改代码来达到目的。如果不想改变程序的运行方式，可以添加一个信号处理函数解决问题（这样对代码修改最少），例如：

static void sighandler( int sig_no )
{
	exit(0);
}
signal( SIGUSR1, sighandler )；

当使用kill -USR1 pid 后，程序退出，生成gmon.out文件。

输出项说明

% 
		函数使用时间占所有时间的百分比
cumulative 
	函数和上列函数累计执行的时间(seconds)
self 
		函数本身所执行的时间(seconds)
calls 		函数被调用的次数
self ms/call 
	每一次调用花费在函数的时间microseconds。
total ms/call 
	每一次调用，花费在函数及其衍生函数的平均时间microseconds。
name		函数名

pasting