5.14.1 程序剖析

程序剖析（profiling）运行程序的一个版本，其中插入了工具代码，以确定程序的各个部分需要多少时间。这对于确认程序中我们需要集中注意力优化的部分是很有用的。剖析的一个有力之处在于可以在现实的基准数据（benchmark data）上运行实际程序的同时，进行剖析。

Unix 系统提供了一个剖析程序 GPROF。这个程序产生两种形式的信息。首先，它确定程序中每个函数花费了多少 CPU 时间。其次，它计算每个函数被调用的次数，以执行调用的函数来分类。这两种形式的信息都非常有用。这些计时给出了不同函数在确定整体运行时间中的相对重要性。调用信息使得我们能理解程序的动态行为。

用 GPROF 进行剖析需要 3 个步骤，就像 C 程序 prog.c 所示，它运行时命令行参数为 file.txt：

程序必须为剖析而编译和链接。使用 GCC（以及其他 C 编译器），就是在命令行上简单地包括运行时标志 -pg。确保编译器不通过内联替换来尝试执行任何优化是很重要的，否则就可能无法正确刻画函数调用。我们使用优化标志 -Og，以保证能正确跟踪函数调用。

linux> gcc -Og -pg prog.c -o prog

然后程序像往常一样执行：

linux> ./prog file.txt

它运行得会比正常时稍微慢一点（大约慢 2 倍），不过除此之外唯一的区别就是它产生了一个文件 gmon.out。

调用 GPROF 来分析 gmon.out 中的数据。

linux> gprof prog

剖析报告的第一部分列出了执行各个函数花费的时间，按照降序排列。作为一个示例，下面列出了报告的一部分，是关于程序中最耗费时间的三个函数的：

  %   cumulative   self              self     total
 time   seconds   seconds    calls  s/call   s/call  name
97.58    203.66    203.66        1  203.66   203.66  sort_words
 2.32    208.50      4.85   965027    0.00     0.00  find_ele_rec
 0.14    208.81      0.30 12511031    0.00     0.00  Strlen

每一行代表对某个函数的所有调用所花费的时间。第一列表明花费在这个函数上的时间占整个时间的百分比。第二列显示的是直到这一行并包括这一行的函数所花费的累计时间。第三列显示的是花费在这个函数上的时间，而第四列显示的是它被调用的次数（递归调用不计算在内）。在例子中，函数 sort_words 只被调用了一次，但就是这一次调用需要 203.66 秒，而函数 find_ele_rec 被调用了 965 027 次（递归调用不计算在内），总共需要 4.85 秒。函数 Strlen 通过调用库函数 strlen 来计算字符串的长度。GPROF 的结果中通常不显示库函数调用。库函数耗费的时间通常计算在调用它们的函数内。通过创建这个“包装函数（wrapper function）”Strlen，我们可以可靠地跟踪对 strlen 的调用，表明它被调用了 12 511 031 次，但是一共只需要 0.30 秒。

剖析报告的第二部分是函数的调用历史。下面是一个递归函数 find_ele_rec 的历史：

158655725             find_ele_rec [5]
             4.85    0.10  965027/965027      insert_string [4]
[5]   2.4    4.85    0.10  965027+158655725   find_ele_rec [5]
             0.08    0.01  363039/363039      save_string [8]
             0.00    0.01  363039/363039      new_ele [12]
158655725             find_ele_rec [5]

这个历史既显示了调用 find_ele_rec 的函数，也显示了它调用的函数。头两行显示的是对这个函数的调用：被它自身递归地调用了 158 655 725 次，被函数 insert_string 调用了 965 027 次（它本身被调用了 965 027 次）。函数 find_ele_rec 也调用了另外两个函数 save_string 和 new_ele，每个函数总共被调用了 363 039 次。

根据这个调用信息，我们通常可以推断出关于程序行为的有用信息。例如，函数 find_ele_rec 是一个递归过程，它扫描一个哈希桶（hash bucket）的链表，查找一个特殊的字符串。对于这个函数，比较递归调用的数量和顶层调用的数量，提供了关于遍历这些链表的长度的统计信息。这里递归与顶层调用的比率是 164.4，我们可以推断出程序每次平均大约扫描 164 个元素。

GPROF 有些属性值得注意：

计时不是很准确。它的计时基于一个简单的间隔计数（interval counting）机制，编译过的程序为每个函数维护一个计数器，记录花费在执行该函数上的时间。操作系统使得每隔某个规则的时间间隔 δ，程序被中断一次。δ 的典型值的范围为 1.0～10.0 毫秒。当中断发生时，它会确定程序正在执行什么函数，并将该函数的计数器值增加 δ。当然，也可能这个函数只是刚开始执行，而很快就会完成，却赋给它从上次中断以来整个的执行花费。在两次中断之间也可能运行其他某个程序，却因此根本没有计算花费。对于运行时间较长的程序，这种机制工作得相当好。从统计上来说，应该根据花费在执行函数上的相对时间来计算每个函数的花费。不过，对于那些运行时间少于 1 秒的程序来说，得到的统计数字只能看成是粗略的估计值。
假设没有执行内联替换，则调用信息相当可靠。编译过的程序为每对调用者和被调用者维护一个计数器。每次调用一个过程时，就会对适当的计数器加 1。
默认情况下，不会显示对库函数的计时。相反，库函数的时间都被计算到调用它们的函数的时间中。