原文:https://www.ibm.com/developerworks/cn/linux/l-gnuprof.html
使用 GNU profiler 来提高代码运行速度
寻找应用程序中占用时间最长的部分
改进应用程序的性能是一项非常耗时耗力的工作,但是究竟程序中是哪些函数消耗掉了大部分执行时间,这通常都不是非常明显的。在本文中我们将学习如何使用 gprof 为 Linux 平台上的用户空间和系统调用精确分析性能瓶颈。
假设我们现在已经有了一个可以工作的应用程序,接下来让我们来看一下如何使用 gprof 来精确测量应用程序执行过程中时间都花费到什么地方去了,这样做的目的是了解一下在什么地方进行优化效果最佳。
gprof 可以对 C、C++、Pascal 和 Fortran 77 应用程序进行剖析。本文中的例子使用的是 C。
清单 1. 耗时的应用程序示例
#include <stdio.h> 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 <No of Iterations>\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 <spontaneous> [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 <stdio.h> 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 <No of Iterations>\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 标志中,并重新执行 emerge
glibc。当这个过程完成之后,就会看到 /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 <stdio.h> 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 <No of Iterations>\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 机器上安装了需要使用的工具。
这是参考另一篇博文的:
有些时候,我们特别关注程序的性能,特别是底层软件,比如驱动程序,OS等。为了更好的优化程序性能,我们必须找到性能瓶颈点,“好钢用在刀刃上”才能取 得好的效果,否则可能白做工作。为了找到关键路径,我们可以使用profilng技术,在Linux平台上,我们可以使用gprof和oprofile工 具。
- gprof是GNU工具之一,它在编译的时候在每个函数的出入口加入了profiling的代码,运行时统计程序在用户态的 执行信息,可以得到每个函数的调用次数,执行时间,调用关系等信息,简单易懂。适合于查找用户级程序的性能瓶颈,对于很多时间都在内核态执行的程 序,gprof不适合。
- oprofile也是一个开源的profiling工具,它使用硬件调试寄存器来统计信息,进 行profiling的开销比较小,而且可以对内核进行profiling。它统计的信息非常的多,可以得到cache的缺失率,memory的访存信 息,分支预测错误率等等,这些信息gprof是得不到的,但是对于函数调用次数,它是不能够得到的。。
简单来说,gprof简单,适合于查找用户级程序的瓶颈,而oprofile稍显复杂,但是得到的信息更多,更适合调试系统软件。
我们以编译运行hello.c为例,来说明如何使用这两个工具,这里不解释具体结果的含义,要想详细了解每个结果代表什么意思,可以看一下参考资料中官方站点上的doc信息,里面会给你详尽的解释。
gprof Quick Start
gprof是gnu binutils工具之一,默认情况下linux系统当中都带有这个工具。
- 使用 -pg 选项来编译hello.c,如果要得到带注释的源码清单,则需要增加 -g 选项。运行: gcc -pg -g -o hello hello.c
- 运行应用程序: ./hello 会在当前目录下产生gmon.out文件
- 使用gprof来分析gmon.out文件,需要把它和产生它的应用程序关联起来:
- gprof hello gmon.out -p 得到每个函数占用的执行时间
- gprof hello gmon.out -q 得到call graph,包含了每个函数的调用关系,调用次数,执行时间等信息。
- gprof hello gmon.out -A 得到一个带注释的“源代码清单”,它会注释源码,指出每个函数的执行次数。这需要在编译的时候增加 -g选项。
oprofile Quick Start
oprofile是sourceforge上面的一个开源项目,在2.6内核上带有这个工具,好像只有smp系统才有。比较老的系统,需要自己安装,重新编译内核。
oprofile是一套工具,分别完成不同的事情。
opcontrol:设置需要收集的事件。
opreport: 对结果进行统计输出。
opannaotate:产生带注释的源/汇编文件,源语言级的注释需要编译源文件时的支持。
opstack: 产生调用图profile,但要求x86/2.6的平台,并且linux2.6安装了call-graph patch
opgprof: 产生如gprof相似的结果。
oparchive: 将所有的原始数据文件收集打包,可以到另一台机器上进行分析。
op_import: 将采样的数据库文件从另一种abi转化成本地格式。
运行oprofile需要root权限,因为它要加载profile模块,启动oprofiled后台程序等。所以在运行之前,就需要切换到root。
- opcontrol --init 加载模块,mout /dev/oprofile 创建必需的文件和目录
- opcontrol --no-vmlinux 或者 opcontrol --vmlinux=/boot/vmlinux-`uname -r` 决定是否对kernel进行profiling
- opcontrol --reset 清楚当前会话中的数据
- opcontrol --start 开始profiling
- ./hello 运行应用程序,oprofile会对它进行profiling
- opcontrol --dump 把收集到的数据写入文件
- opcontrol --stop 停止profiling
- opcotrol -h 关闭守护进程oprofiled
- opcontrol --shutdown 停止oprofiled
- opcontrol --deinit 卸载模块
常用的是3→7这几个过程,得到性能数据之后,可以使用opreport, opstack, opgprof, opannotate几个工具进行分析,我常用的是opreport, opannotate进行分析。
- opreport使用 http://oprofile.sourceforge.net/doc/opreport.html
- opannotate使用 http://oprofile.sourceforge.net/doc/opannotate.html
- opgprof使用 http://oprofile.sourceforge.net/doc/opgprof.html
最常用的是opreport,这个可以给出image和symbols的信息,比如我想得到每个函数的执行时间占用比例等信息,用来发现系统性能瓶颈。opannotate可以对源码进行注释,指出哪个地方占用时间比较多。常用命令如下:
- opreport -l /bin/bash --exclude-depand --threshold 1 , 用来发现系统瓶颈。
- opannotate --source --output-dir=annotated /usr/local/oprofile-pp/bin/oprofiled
- opannotate --source --base-dirs=/tmp/build/libfoo/ --search-dirs=/home/user/libfoo/ --output-dir=annotated/ /lib/libfoo.so
网络资源
- gprof 用户手册 http://sourceware.org/binutils/docs-2.17/gprof/index.html
- oprofile官方站点 http://oprofile.sourceforge.net/
- 使用 GNU profiler 来提高代码运行速度 http://www-128.ibm.com/developerworks/cn/linux/l-gnuprof.html
- 使用 OProfile for Linux on POWER 识别性能瓶颈 http://www-128.ibm.com/developerworks/cn/linux/l-pow-oprofile/