profiler

简介

各种软件对于性能的需求可能会有很大的区别，但是很多应用程序都有非常严格的性能需求，这一点并不奇怪。电影播放器就是一个很好的例子：如果一个电影播放器只能以所需要速度的 75% 来播放电影，那么它几乎就没什么用处了。

其他应用程序（例如视频编码）如果是耗时非常长的操作，最好以 “批处理” 任务的方式运行，此时启动一个作业，让其一直运行，然后我们就可以去干别的事情了。尽管这些类型的应用程序没有这种硬性性能指标的限制，但是提高速度仍然会带来很多好处，例如可以在给定的时间内可以对更多电影进行编码，在同样的时间内可以以更高的品质进行编码。

通常，除了最简单的应用程序之外，对于其他应用程序来说，性能越好，这个应用程序的用处就越大，也就会越流行。由于这个原因，性能考虑是（也应该是）很多应用程序开发人员脑袋中的第一根弦。

不幸的是，很多尝试让应用程序速度更快的努力都白费了，因为开发人员通常都是对自己的软件进行一些小型的优化，而没有去研究程序在更大的范围内是如何操作的。例如，我们可能会花费大量的时间来让某个特定函数的运行速度达到原来的两倍，这一点非常不错，但是如果这个函数很少被调用（例如打开文件），那么将这个函数的执行时间从 200ms 减少到 100ms，对于整个软件的总体执行时间来说并不会有太大的影响。

有效地利用您的时间的方法是，尽量优化软件中被频繁调用的部分。例如，假设应用程序花了 50% 的时间在字符串处理函数上，如果可以对这些函数进行优化，提高 10% 的效率，那么应用程序的总体执行时间就会改进 5%。

因此，如果希望能够有效地对程序进行优化，那么精确地了解时间在应用程序中是如何花费的，以及真实的输入数据，这一点非常重要。这种行为就称为代码剖析（code profiling）。本文将简要介绍 GNU 编译器工具包所提供的一种剖析工具，它的名字让人可以产生无限遐想，叫 GNU profiler（gprof）。本文主要面向那些开放源码软件开发工具的新手。

gprof 来救援了

在开始介绍如何使用 gprof 之前，需要首先了解一下在整个开发周期中，剖析应该在何处进行。通常来说，编写代码应该有 3 个目标，按照重要性的次序分别如下所示：

保证软件可以正确地工作。这通常是开发过程的重点。通常，如果一个软件根本连我们期望它做的事情都实现不了，那么即使它运行速度非常快，也根本没有任何意义！显然，正确性在某些情况下可能并不是至关重要的；例如，如果一个电影播放器可以正确地播放 99% 的电影文件，但是偶然会有些显示问题，那它依然可以使用。但是通常来说，正确性要远远比速度更加重要。

保证软件是可维护的。这实际上是第一个目标的一个子项。通常，如果软件编写得可维护性不好，那么即使它最开始时可以很好地工作，很快您（或其他人）在修正 bug 或添加新特性时可能也会破坏程序的正确性。

让软件可以快速运行。这就是剖析的用武之地。当软件可以正确运行之后，我们就可以开始剖析的过程来帮助它更快地运行了。

假设我们现在已经有了一个可以工作的应用程序，接下来让我们来看一下如何使用 gprof 来精确测量应用程序执行过程中时间都花费到什么地方去了，这样做的目的是了解一下在什么地方进行优化效果最佳。

gprof 可以对 C、C++、Pascal 和 Fortran 77 应用程序进行剖析。本文中的例子使用的是 C。

清单 1. 耗时的应用程序示例

#include

int a(void) {

int i=0,g=0;

while(i++<100000)

{

g+=i;

}

return g;

}

int b(void) {

int i=0,g=0;

while(i++<400000)

{

g+=i;

}

return g;

}

int main(int argc, char** argv)

{

int iterations;

if(argc != 2)

{

printf("Usage %s \\n", argv[0]);

exit(-1);

}

else

iterations = atoi(argv[1]);

printf("No of iterations = %d\\n", iterations);

while(iterations--)

{

a();

b();

}

}

正如我们从代码中可以看到的，这个非常简单的应用程序包括两个函数：a和b，它们都处于一个繁忙的循环中消耗 CPU 周期。main函数中采用了一个循环来反复调用这两个函数。第二个函数b循环的次数是a函数的 4 倍，因此我们期望在对代码分析完之后，可以看出大概有 20% 的时间花在了a函数中，而 80% 的时间花在了b函数中。下面就开始剖析代码，并看一下我们的这些期望是否正确。

启用剖析非常简单，只需要在 gcc 编译标志中加上-pg即可。编译方法如下：

gcc example1.c -pg -o example1 -O2 -lc

在编译好这个应用程序之后，可以按照普通方式运行这个程序：

./example1 50000

当这个程序运行完之后，应该会看到在当前目录中新创建了一个文件 gmon.out。

使用输出结果

首先看一下 “flat profile”，我们可以使用gprof命令获得它，这需要为其传递可执行文件和 gmon.out 文件作为参数，如下所示：

gprof example1 gmon.out -p

这会输出以下内容：

清单 2. flat profile 的结果

Flat profile:

Each sample counts as 0.01 seconds.

%   cumulative   self              self     total

time   seconds   seconds    calls  ms/call  ms/call  name

80.24     63.85    63.85    50000     1.28     1.28  b

20.26     79.97    16.12    50000     0.32     0.32  a

从这个输出结果中可以看到，正如我们期望的一样，b函数所花费的时间大概是a函数所花费的时间的 4 倍。真正的数字并不是十分有用；由于取整舍入错误，这些数字可能并不是非常精确。

聪明的读者可能会注意到，很多函数调用（例如printf）在这个输出中都没有出现。这是因为这些函数都是在 C 运行时库（libc.so）中的，（在本例中）它们都没有使用-pg进行编译，因此就没有对这个库中的函数收集剖析信息。稍后我们会回到这个问题上来。

接下来我们希望了解的是 “call graph”，这可以通过下面的方式获得：

gprof example1 gmon.out -q

这会输出下面的结果。

清单 3. Call graph

Call graph (explanation follows)

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

index % time    self  children    called     name

[1]    100.0    0.00   79.97                 main [1]

63.85    0.00   50000/50000       b [2]

16.12    0.00   50000/50000       a [3]

-----------------------------------------------

63.85    0.00   50000/50000       main [1]

[2]     79.8   63.85    0.00   50000         b [2]

-----------------------------------------------

16.12    0.00   50000/50000       main [1]

[3]     20.2   16.12    0.00   50000         a [3]

-----------------------------------------------

最后，我们可能会希望获得一个 “带注解的源代码” 清单，它会将源代码输出到应用程序中，并加上每个函数被调用了多少次的注释。

要使用这种功能，请使用启用调试功能的标志来编译源代码，这样源代码就会被加入可执行程序中：

gcc example1.c -g -pg -o example1 -O2 -lc

像以前一样重新运行这个应用程序：

./example1 50000

gprof命令现在应该是：

gprof example1 gmon.out -A

这会输出下面的结果：

清单 4. 带注释的源代码

*** File /home/martynh/profarticle/example1.c:

#include

50000 -> int a(void) {

int i=0,g=0;

while(i++<100000)

{

g+=i;

}

return g;

}

50000 -> int b(void) {

int i=0,g=0;

while(i++<400000)

{

g+=i;

}

return g;

}

int main(int argc, char** argv)

##### -> {

int iterations;

if(argc != 2)

{

printf("Usage %s \\n", argv[0]);

exit(-1);

}

else

iterations = atoi(argv[1]);

printf("No of iterations = %d\\n", iterations);

while(iterations--)

{

a();

b();

}

}

Top 10 Lines:

Line      Count

3      50000

11      50000

Execution Summary:

3   Executable lines in this file

3   Lines executed

100.00   Percent of the file executed

100000   Total number of line executions

33333.33   Average executions per line

共享库的支持

正如在前面曾经介绍的，对于代码剖析的支持是由编译器增加的，因此如果希望从共享库（包括 C 库 libc.a）中获得剖析信息，就需要使用-pg来编译这些库。幸运的是，很多发行版都提供了已经启用代码剖析支持而编译的 C 库版本（libc_p.a）。

在我使用的发行版 gentoo 中，需要将 “profile” 添加到 USE 标志中，并重新执行emergeglibc。当这个过程完成之后，就会看到 /usr/lib/libc_p.a 文件已经创建好了。对于没有按照标准提供 libc_p 的发行版本来说，需要检查它是否可以单独安装，或者可能需要自己下载 glibc 的源代码并进行编译。

在获得 libc_p.a 文件之后，就可以简单地重新编译前面的例子了，方法如下：

gcc example1.c -g -pg -o example1 -O2 -lc_p

然后，可以像以前一样运行这个应用程序，并获得 flat profile 或 call graph，应该会看到很多 C 运行函数，包括printf（这些函数在我们的测试函数中并不是太重要）。

用户时间与内核时间

现在我们已经知道如何使用 gprof 了，接下来可以简单且有效地对应用程序进行分析了，希望可以消除性能瓶颈。

不过现在您可能已经注意到了 gprof 的最大缺陷：它只能分析应用程序在运行过程中所消耗掉的用户时间。通常来说，应用程序在运行时既要花费一些时间来运行用户代码，也要花费一些时间来运行 “系统代码”，例如内核系统调用。

如果对清单 1 稍加修改，就可以清楚地看出这个问题：

清单 5. 为清单 1 添加系统调用分析功能

#include

int a(void) {

sleep(1);

return 0;

}

int b(void) {

sleep(4);

return 0;

}

int main(int argc, char** argv)

{

int iterations;

if(argc != 2)

{

printf("Usage %s \\n", argv[0]);

exit(-1);

}

else

iterations = atoi(argv[1]);

printf("No of iterations = %d\\n", iterations);

while(iterations--)

{

a();

b();

}

}

正如您可以看到的，我们对清单 1 中的代码进行了修改，现在a函数和b函数不再只处理繁忙的循环了，而是分别调用 C 运行时函数sleep来挂起执行 1 秒和 4 秒。

像以前一样编译这个应用程序：

gcc example2.c -g -pg -o example2 -O2 -lc_p

并让这个程序循环 30 次：

./example2 30

所生成的 flat profile 如下所示：

清单 6. flat profile 显示了系统调用的结果

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      120     0.00     0.00  sigprocmask

0.00      0.00     0.00       61     0.00     0.00  __libc_sigaction

0.00      0.00     0.00       61     0.00     0.00  sigaction

0.00      0.00     0.00       60     0.00     0.00  nanosleep

0.00      0.00     0.00       60     0.00     0.00  sleep

0.00      0.00     0.00       30     0.00     0.00  a

0.00      0.00     0.00       30     0.00     0.00  b

0.00      0.00     0.00       21     0.00     0.00  _IO_file_overflow

0.00      0.00     0.00        3     0.00     0.00  _IO_new_file_xsputn

0.00      0.00     0.00        2     0.00     0.00  _IO_new_do_write

0.00      0.00     0.00        2     0.00     0.00  __find_specmb

0.00      0.00     0.00        2     0.00     0.00  __guard_setup

0.00      0.00     0.00        1     0.00     0.00  _IO_default_xsputn

0.00      0.00     0.00        1     0.00     0.00  _IO_doallocbuf

0.00      0.00     0.00        1     0.00     0.00  _IO_file_doallocate

0.00      0.00     0.00        1     0.00     0.00  _IO_file_stat

0.00      0.00     0.00        1     0.00     0.00  _IO_file_write

0.00      0.00     0.00        1     0.00     0.00  _IO_setb

0.00      0.00     0.00        1     0.00     0.00  ____strtol_l_internal

0.00      0.00     0.00        1     0.00     0.00  ___fxstat64

0.00      0.00     0.00        1     0.00     0.00  __cxa_atexit

0.00      0.00     0.00        1     0.00     0.00  __errno_location

0.00      0.00     0.00        1     0.00     0.00  __new_exitfn

0.00      0.00     0.00        1     0.00     0.00  __strtol_internal

0.00      0.00     0.00        1     0.00     0.00  _itoa_word

0.00      0.00     0.00        1     0.00     0.00  _mcleanup

0.00      0.00     0.00        1     0.00     0.00  atexit

0.00      0.00     0.00        1     0.00     0.00  atoi

0.00      0.00     0.00        1     0.00     0.00  exit

0.00      0.00     0.00        1     0.00     0.00  flockfile

0.00      0.00     0.00        1     0.00     0.00  funlockfile

0.00      0.00     0.00        1     0.00     0.00  main

0.00      0.00     0.00        1     0.00     0.00  mmap

0.00      0.00     0.00        1     0.00     0.00  moncontrol

0.00      0.00     0.00        1     0.00     0.00  new_do_write

0.00      0.00     0.00        1     0.00     0.00  printf

0.00      0.00     0.00        1     0.00     0.00  setitimer

0.00      0.00     0.00        1     0.00     0.00  vfprintf

0.00      0.00     0.00        1     0.00     0.00  write

如果对这个输出结果进行分析，我们就会看到，尽管 profiler 已经记录了每个函数被调用的确切次数，但是为这些函数记录的时间（实际上是所有函数）都是 0.00。这是因为sleep函数实际上是执行了一次对内核空间的调用，从而将应用程序的执行挂起了，然后有效地暂停执行，并等待内核再次将其唤醒。由于花在用户空间执行的时间与花在内核中睡眠的时间相比非常小，因此就被取整成零了。其原因是 gprof 仅仅是通过以固定的周期对程序运行时间进行采样测量来工作的。因此，当程序不运行时，就不会对程序进行采样测量。

这实际上是一把双刃剑。从一个方面来说，这使得有些程序非常难以进行优化，例如花费大部分时间在内核空间的程序，或者由于外部因素（例如操作系统的 I/O 子系统过载）而运行得非常慢的程序。从另一个方面来说，这意味着剖析不会受到系统中其他事件的影响（例如另外一个用户使用了大量的 CPU 时间）。

通常，有一个很好的基准测试可以用来查看 gprof 对于帮助对应用程序进行优化是多么有用，方法是在time命令下面执行它。这个命令会显示一个应用程序运行完成需要多少时间，并可以测量它在用户空间和内核空间各花费了多少时间。

如果查看一下清单 2 中的例子：

time ./example2 30

输出结果应该如下所示：

清单 7. time 命令的输出结果

No of iterations = 30

real    2m30.295s

user    0m0.000s

sys     0m0.004s

我们可以看出几乎没有多少时间被花费在执行用户空间的代码上，因此 gprof 在此处不会非常有用。

结束语

尽管 gprof 存在上面的限制，但是它对于优化代码来说依然是个非常有用的工具，如果您的代码大部分是用户空间 CPU 密集型的，它的用处就更加明显。首先使用time来运行程序从而判断 gprof 是否能产生有用信息是个好主意。

如果 gprof 不适合您的剖析需要，那么还有其他一些工具可以克服 gprof 部分缺陷，包括 OProfile 和 Sysprof （请参看参考资料中有关这些工具信息的链接）。

从另一个方面来说，假设我们已经安装了 gcc，gprof 相对于其他工具来说，一个主要的优点是很可能早已在 Linux 机器上安装了需要使用的工具。

Gprof产生的信息解释：

%time    

该函数消耗时间占程序所有时间百分比

Cumulative Seconds

程序的累积执行时间 (只是包括gprof能够监控到的函数）

Self seconds

该函数本身执行时间（所有被调用次数的合共时间）

Calls

函数被调用次数

Self  TS/call

函数平均执行时间（不包括被调用时间）（函数的单次执行时间）

TotalTS/call

函数平均执行时间（包括被调用时间）

name

（函数的单次执行时间）函数名

Call Graph的字段含义：

Index  

索引值

%time

函数消耗时间占所有时间百分比

Self

函数本身执行时间

Children

执行子函数所用时间

Called

被调用次数

Name

函数名