XXX
分类： LINUX
2014-03-31 11:01:44
原文地址：使用 GNU profiler 来提高代码运行速度 作者：自语的骆驼
即使它运行速度非常快，也根本没有任何意义！显然，正确性在某些情况下可能并不是至关重要的；例如，如果一个电影播放器可以正确地播放 99% 的电影文件，但是偶然会有些显示问题，那它依然可以使用。但是通常来说，正确性要远远比速度更加重要。 假设我们现在已经有了一个可以工作的应用程序，接下来让我们来看一下如何使用 gprof 来精确测量应用程序执行过程中时间都花费到什么地方去了，这样做的目的是了解一下在什么地方进行优化效果最佳。 gprof 可以对 C、C++、Pascal 和 Fortran 77 应用程序进行剖析。本文中的例子使用的是 C。 清单 1. 耗时的应用程序示例 #include int a(void) { int i=0,g=0; while(i++\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++ int b(void) { int i=0,g=0; while(i++ { 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 标志中，并重新执行 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 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 机器上安装了需要使用的工具。 |
