GNU gprof 的使用以及常见问题

gprof 对于 profiling 非常有用,不过初学者可能会遇到一些障碍。下面我们从最简单的例子开始,一步步深入,希望能够容易明白一点了。

$ uname -a
Linux dev 2.4.21-9.30AXsmp #1 SMP Wed May 26 23:37:09 EDT 2004 i686 i686 i386 GNU/Linux

$ gprof --version
GNU gprof 2.14.90.0.4
Based on BSD gprof, copyright 1983 Regents of the University of California.
This program is free software. This program has absolutely no warranty.

$ cat foo.c

int main(void)
{
    printf("hello world\n");
    return 0;
}

$ gcc -g -pg foo.c

$ ./a.out
hello world

$ gprof
gprof: gmon.out file is missing call-graph data

这个结果有点莫名其妙。难道这个简单的一个例子都过不了?其实这是 gprof 的一个“feature”,也许是专门用来迷惑初学者的。出错的原因参见:http://gcc.gnu.org/ml/gcc-help/2006-06/msg00037.html,是我们的函数过于简单,其中没有什么函数调用导致的。

让我们换个复杂一点的例子看看。

$ cat bar.c

static int sub(void);

int main(void)
{
    int i;

    printf("hello world\n");

    for (i = 0; i < 10; i++)
        sub();

    return 0;
}

static int sub(void)
{
    return 0;
}

$ gcc -g -pg bar.c
$ ./a.out
hello world

注意这次输出的信息正常了,不过显得有点罗嗦。后面我们将采用“gprof -b”简化之。命令“gprof”其实就是“gprof a.out gmon.out”。

$ gprof
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 10 0.00 0.00 sub

% 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.

total the average number of milliseconds spent in this
ms/call function and its descendents per call, if this
function is profiled, else blank.

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.

Call graph (explanation follows)

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

index % time self children called name
0.00 0.00 10/10 main [8]
[1] 0.0 0.00 0.00 10 sub [1]
-----------------------------------------------

This table describes the call tree of the program, and was sorted by
the total amount of time spent in each function and its children.

Each entry in this table consists of several lines. The line with the
index number at the left hand margin lists the current function.
The lines above it list the functions that called this function,
and the lines below it list the functions this one called.
This line lists:
index A unique number given to each element of the table.
Index numbers are sorted numerically.
The index number is printed next to every function name so
it is easier to look up where the function in the table.

% time This is the percentage of the `total' time that was spent
in this function and its children. Note that due to
different viewpoints, functions excluded by options, etc,
these numbers will NOT add up to 100%.

self This is the total amount of time spent in this function.

children This is the total amount of time propagated into this
function by its children.

called This is the number of times the function was called.
If the function called itself recursively, the number
only includes non-recursive calls, and is followed by
a `+' and the number of recursive calls.

name The name of the current function. The index number is
printed after it. If the function is a member of a
cycle, the cycle number is printed between the
function's name and the index number.

For the function's parents, the fields have the following meanings:

self This is the amount of time that was propagated directly
from the function into this parent.

children This is the amount of time that was propagated from
the function's children into this parent.

called This is the number of times this parent called the
function `/' the total number of times the function
was called. Recursive calls to the function are not
included in the number after the `/'.

name This is the name of the parent. The parent's index
number is printed after it. If the parent is a
member of a cycle, the cycle number is printed between
the name and the index number.

If the parents of the function cannot be determined, the word
`<spontaneous>' is printed in the `name' field, and all the other
fields are blank.

For the function's children, the fields have the following meanings:

self This is the amount of time that was propagated directly
from the child into the function.

children This is the amount of time that was propagated from the
child's children to the function.

called This is the number of times the function called
this child `/' the total number of times the child
was called. Recursive calls by the child are not
listed in the number after the `/'.

name This is the name of the child. The child's index
number is printed after it. If the child is a
member of a cycle, the cycle number is printed
between the name and the index number.

If there are any cycles (circles) in the call graph, there is an
entry for the cycle-as-a-whole. This entry shows who called the
cycle (as parents) and the members of the cycle (as children.)
The `+' recursive calls entry shows the number of function calls that
were internal to the cycle, and the calls entry for each member shows,
for that member, how many times it was called from other members of
the cycle.

 

Index by function name

[1] sub (bar.c)

$ gprof -b
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 10 0.00 0.00 sub

Call graph

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

index % time self children called name
0.00 0.00 10/10 main [8]
[1] 0.0 0.00 0.00 10 sub [1]
-----------------------------------------------

Index by function name

[1] sub (bar.c)

gprof 的这个特性很容易让初学者迷惑,可能一上来就把人吓跑了。我们再写个复杂一点点的例子,应该更容易看出 gprof 的用处了。

$ cat bar.c

static int sub(void);
static int sub2(void);

int main(void)
{
    sub();
    sub2();

    return 0;
}

static int sub(void)
{
    int i;
    int res = 0;

    for (i = 0; i < 10000000; i++)
        res += i;

    return res;
}

static int sub2(void)
{
    int i;
    int res = 0;

    for (i = 0; i < 10000000; i++)
        res *= i;

    return res;
}

$ gcc -g -pg bar.c

$ ./a.out

$ gprof -b
Flat profile:

Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ms/call ms/call name
53.33 0.08 0.08 1 80.00 80.00 sub2
46.67 0.15 0.07 1 70.00 70.00 sub

Call graph

granularity: each sample hit covers 4 byte(s) for 6.67% of 0.15 seconds

index % time self children called name
<spontaneous>
[1] 100.0 0.00 0.15 main [1]
0.08 0.00 1/1 sub2 [2]
0.07 0.00 1/1 sub [3]
-----------------------------------------------
0.08 0.00 1/1 main [1]
[2] 53.3 0.08 0.00 1 sub2 [2]
-----------------------------------------------
0.07 0.00 1/1 main [1]
[3] 46.7 0.07 0.00 1 sub [3]
-----------------------------------------------

Index by function name

[3] sub (bar.c) [2] sub2 (bar.c)

当然了,上面给出的程序都非常简单,完全不能反映实际开发工作中的要求。实际的程序大多是多线程或多进程的,而且代码一般都比较复杂。如果我们用 gprof 来分析一个多进程的程序,很可能会发现一个进程的输出文件 gmon.out 覆盖了另外一个进程的输出文件,导致最后只能看到最后的一个。这肯定不是我们想要的结果。Google 告诉我们有一些解决办法,其中下面这个办法最简单了。在执行程序之前,进行:

$ export GMON_OUT_PREFIX=x.out

从此以后,生成的文件名将类似于 x.out.<进程的pid> 了,它们不再互相覆盖了。Google 也许会告诉你更多其它的办法。如果我们用 grof 来分析一个多线程的程序,则很可能会发现 gprof 处理不了子线程。很明显,这也不是我们期望的结果。对于这个问题,http://sam.zoy.org/writings/programming/gprof.html给出了一个不错的解决办法。

Written on October 14, 2005