程序的“听诊器”——性能监视工具
听诊器是一种简单工具，却给医生的工作带来了革命：它让内科医生能有效地监控病人的身体。性能监视工具（profiler）对程序起着同样的作用。
你现在用什么工具来研究程序？复杂的分析系统很多，既有交互式调试器，又有程序动画系统。正如CT扫描仪永远代替不了听诊器一样，复杂的软件也永远代替不了程序员用来监控程序的最简单工具——性能监视工具，我们用它了解程序各部分的执行频率。
本文先用两种性能监视工具来加速一个小程序（记住真正的目的是说明性能监视工具）。后续各节简要介绍性能监视工具的各种用途、非过程语言的性能监视工具，以及开发性能监视工具的技术。
1 计算素数
程序P1是个ANSI标准C程序，依次打印所有小于1000的素数。
程序P1
int prime(int n)
{ int i;
999 for (i = 2; i < n; i++)
78022 if(n%i == 0)
831 return 0;
168 return 1;
}
main()
{ int i, n；
1 n = 1000；
1 for (i = 2; i <= n; i++)
999 if (prime(i))
168 printf("%dn", i);
}
如果整型参数n是素数，上述prime函数返回1（真），否则返回0。这个函数检验2到n-1之间的所有整数，看其是否整除n。上述main过程用prime子程序来依次检查整数2～1000，发现素数就打印出来。
我像写任何一个C程序那样写好程序P1，然后在性能监视选项下进行编译。在程序运行之后，只要一个简单的命令就生成了前面所示的列表。（我稍微改变了一些输出的格式。）每行左侧的数由性能监视工具生成，用于说明相应的行执行了多少次。例如，main函数调用了1次，其中测试了999个整数，找出了168个素数。函数prime被调用了999次，其中168次返回1，另外831次返回0（快速验证：168+ 831=999）。prime函数共测试了78022个可能的因子，或者说为了确定素数性，对每个整数检查了大约78个因子。
程序P1是正确的，但是很慢。在VAX-11/750上，计算出小于1000的所有素数约需几秒钟，但计算出小于10 000的所有素数却需要3分钟。对这些计算的性能监视表明，大多数时间花在了测试因子上。因而下一个程序只对n考虑不超过sqrt n 的可能的整数因子。整型函数root先把整型参数转换成浮点型，然后调用库函数sqrt，最后再把浮点型结果转换回整型。程序P2包含两个旧函数和这个新函数root。
程序P2
int root(int n)
5456 { return (int) sqrt((float) n); }
int prime(int n)
{ int i;
999 for (i = 2; i < = root(n); i++)
5288 if (n % i == 0)
831 return 0;
168 return 1;
}
main()
{ int i, n;
1 n = 1000;
1 for (i = 2; i < = n; i++)
999 if (prime(i))
168 printf("%dn", i);
}
修改显然是有效的：程序P2的行计数显示，只测试了5288个因子（程序P1的1/14），总共调用了5456次root（测试了5288次整除性，168次由于i超出了root(n)而终止循环）。不过，虽然计数大大减少了，但是程序P2运行了5.8秒，而程序P1只运行了2.4秒（本节末尾的表中含有运行时间的更多细节）。这说明什么呢？
迄今为止，我们只看到了行计数（line-count）性能监视。过程时间（procedure-time）性能监视给出了较少的控制流细节，但更多地揭示了CPU时间：
%time cumsecs #call ms/call name
82.7 4.77 _sqrt
4.5 5.03 999 0.26 _prime
4.3 5.28 5456 0.05 _root
2.6 5.43 _frexp
1.4 5.51 _ _doprnt
1.2 5.57 _write
0.9 5.63 mcount
0.6 5.66 _creat
0.6 5.69 _printf
0.4 5.72 1 25.00 _main
0.3 5.73 _close
0.3 5.75 _exit
0.3 5.77 _isatty
过程按照运行时间递减的顺序列出。时间上既显示出总秒数，也显示出占总时间的百分比。编译后记录下源程序中main、prime和root这3个过程的调用次数。再次看到这几个计数是令人鼓舞的。其他过程没有性能监视的库函数，完成各种输入/输出和清理维护工作。第4列说明了带语句计数的所有函数每次调用的平均毫秒数。
过程时间性能监视说明，sqrt占用CPU时间的最多：该函数共被调用5456次，for循环的每次测试都要调用一次sqrt。程序P3通过把sqrt调用移到循环之外，使得在prime的每次调用中只调用一次费时的sqrt过程。
程序P3
int prime(int n)
{ int i, bound;
999 bound = root(n);
999 for (i = 2; i < = bound; i++)
5288 if (n % i == 0)
831 return 0;
168 return 1;
}
当n=1000时，程序P3的运行速度大约是程序P2的4倍，而当n= 100 000时则超过10倍。以n= 100 000的情形为例，过程时间性能监视显示，sqrt占用了程序P2的88%的运行时间，但是只占用了程序P3的48%的运行时间。这好多了，但仍然是循环的累赘。
程序P4合并了另外两个加速措施。首先，程序P4通过对被2、3和5整除的特殊检验，避免了近3/4的开方运算。语句计数表明，被2整除的性质大约把一半的输入归入合数，被3整除把剩余输入的1/3归入合数，被5整除再把剩下的这些数的1/5归入合数。其次，只考虑奇数作为可能的因子，在剩余的数中避免了大约一半的整除检验。它比程序P3大约快两倍，但是也比P3的错误更多。下面是（带错的）程序P4，你能通过检查语句计数看出问题吗？
程序P4
int root(int n)
265 { return (int) sqrt((float) n); }
int prime(int n)
{ int i, bound;
999 if (n % 2 == 0)
500 return 0;
499 if (n % 3 == 0)
167 return 0;
332 if (n % 5 == 0)
67 return 0;
265 bound = root(n);
265 for (i = 7; i <= bound; i = i+2)
1530 if (n % i == 0)
100 return 0;
165 return 1;
}
main()
{ int i, n;
1 n = 1000;
1 for (i = 2; i <= n; i++)
999 if (prime(i))
165 printf("%dn", i);
}
先前的程序找到168个素数，而程序P4只找到165个。丢失的3个素数在哪里？对了，我把3个数作为特殊情形，每个数都引入了一处错误：prime报告2不是素数，因为它被2整除。对于3和5，存在类似的错误。正确的检验是
if (n % 2 == 0)
return (n == 2);
依此类推。如果n被2整除，如果n是2就返回1，否则返回0。对于n=1000、10 000和100 000，程序P4的过程时间性能监视结果总结在下表中。
程序P5比程序P4快，并且有个好处：正确。它把费时的开方运算换成了乘法，如以下程序片段所示。
程序P5的片段
265 for (i = 7; i*i <= n; i = i+2)
1530 if (n % i == 0)
100 return 0;
165 return 1;
它还加入了对被2、3、5整除的正确检验。程序P5总的加速大约有20%。
最后的程序只对已被判定为素数的整数检验整除性；程序P6在1.4节，用Awk语言写成。C实现的过程时间性能监视结果表明，在n=1 000时，49%的运行时间花在prime和main上（其余是输入/输出）；而当n=100 000时，88%的运行时间花在这两个过程上。
下面这个表总结了我们已经看到的这几个程序。表中还包含另外两个程序作为测试基准。程序Q1用习题答案2中的埃氏筛法程序计算素数。程序Q2测量输入/输出开销。对于n=1 000，它打印整数1, 2,…, 168；对于一般的n，它打印整数1, 2,…, P(n)，其中P(n)是比n小的素数的个数。
以上集中讲述了性能监视的一种用途：当你调优单个子过程或函数的性能时，性能监视工具能告诉你运行时间都花在了哪里。
2 使用性能监视工具
对于小程序来说，性能监视很容易实现，因此性能监视工具是可有可无的；但是对于开发大软件来说，性能监视工具则是不可或缺的。Brian Kernighan曾经使用行计数性能监视工具，研究了一个用于解释Awk语言程序的4000行的C程序。那时这个Awk解释程序已广泛使用了多年。扫描该程序75页长的程序清单就会发现，大多数计数都是成百上千的，有些甚至上万。一段晦涩的初始化代码，计数接近百万。Kernighan对一个6行的循环做了几处修改，程序速度就提高了一倍。他自己可能永远也猜不出程序的问题源头所在，但是性能监视工具引导他找到了。
Kernighan的这一经历是相当典型的。“一个程序中不到4%的语句通常占用了一半以上的运行时间。”对许多语言和系统的大量研究表明，对于不处理I/O密集型的大多数程序，大部分的运行时间花在了很小一部分代码上。这种模式是下述经验的基础：
Knuth在论文中描述了用行计数性能监视工具进行自我分析的结果。性能监视结果表明，一半的运行时间花在了两个循环上。结果花了不到一小时修改了几行代码，就让这个性能监视工具的速度提高了一倍。
性能监视结果说明，一个1000行的程序把80%的时间花在一个5行的子程序上。把这个子程序改写成十几行，就让程序的速度提高了一倍。
1984年贝尔实验室的Tom Szymanski打算给一个大系统提速，结果却使该系统慢了10%。他删除了修改的部分，然后多打开了一些性能监视选项以查明失败原因。他发现占用的存储空间增加到了原来的20倍，行计数显示存储空间的分配次数远多于释放次数。接下来用一条指令就纠正了错误，正确的实现让系统加速了一倍。
性能监视表明，操作系统一半的时间花在一个只有少数几条指令的循环上。改写微代码中的这个循环带来一个量级的提速，但是系统的吞吐量不变：性能组已经优化了系统的空闲循环！
这些经历引出了上一节粗略提到过的一个问题：应当在什么输入上监视程序的性能？查找素数的程序只有一个输入n，该输入强烈影响到时间性能监视：对于小的n，输入/输出占大头；对于大的n，计算占大头。有的程序的性能监视结果对输入数据非常不敏感。我猜想大多数计算薪水的程序都有相当一致的性能监视结果，至少从2月到11月如此。但有的程序的性能监视结果会随输入不同有巨大变化。难道你从没有察觉到，你的系统被调整得在制造商的基准数据上运行起来风驰电掣，而处理起你的重要任务时却慢如蜗牛？仔细挑选你的输入数据吧。
性能监视工具对于性能之外的任务也有用。在找素数的练习中，它指出了程序P4的一个错误。行计数在估计测试覆盖面时极有价值，比如，如果出现零，则说明有代码未测试。DEC公司的Dick Sites这样描述性能监视的其他用途：“(1) 在两层微存储实现中，决定哪些微代码放到芯片上；(2) 贝尔北方研究院（Bell Northern Research）的一位朋友某个周末在带有多重异步任务的实时电话交换软件系统上实现了语句计数。通过查看异常计数，他发现了现场安装的代码中存在6处错误，所有错误都涉及不同任务之间的交互。其中一处错误用常规调试技术无法成功追踪到，其余错误还没有被当作问题（也就是说，这些错误症状可能已经发生，但是没有人能够将其归结为具体的软件错误）。”
3 专用的性能监视工具
到目前为止我们所看到的性能监视工具的原理，适用于从汇编和Fortran直到Ada这样的程序设计语言，但是很多程序员现在使用更强大的语言。如何监视Lisp或APL程序的计算性能？又如何监视网络或数据库语言程序的计算性能？
我们打算用UNIX的管道（pipeline）作为更有趣的计算模型的例子。管道是一系列的过滤程序（filter）：当数据流经每个过滤程序时，对数据施加变换。下面这个经典的管道按照频率递减顺序打印某文件中使用最多的25个单词。
cat $* ¦
tr -cs A-Za-z ' 12' ¦
tr A-Z a-z ¦
sort ¦
uniq -c ¦
sort -r –n ¦
sed 25q
当用这个管道在一本大约6万字的书中寻找25个最常见的单词时，我们监视这个管道的性能。输出的前6行是：
3463 the
1855 a
1556 of
1374 to
1166 in
1104 and
...
下面是对VAX-11/750上计算的“管道性能监视”：
lines words chars times
10717 59701 342233 14.4u 2.3s 18r tr -cs A-Za-z 12
57652 57651 304894 11.9u 2.2s 15r tr A-Z a-z
57652 57651 304894 104.9u 7.5s 123r sort
57652 57651 304894 24.5u 1.6s 27r uniq –c
4731 9461 61830 27.0u 1.6s 31r sort -rn
4731 9461 61830 0.0u 0.2s 0r sed 25q
25 50 209
左边几列说明每个阶段的数据：行数、单词数、字符数。右边部分描述了数据阶段之间的过滤程序：用秒表示的用户时间、系统时间以及真实时间，后面是命令本身。
这个性能监视结果给出了程序员感兴趣的许多信息。这个管道是快速的，处理150页的书只需3.5分钟。第一次排序花了这个管道57%的运行时间，这种经过仔细调优的实用程序很难再提速了。第二次排序只花了这个管道14%的时间，但是还有调优的余地。这个性能监视结果还发现了管道中隐藏的一处小错误。UNIX高手们会乐于找出引入空行的地方。
这个性能监视结果也透露了文件中单词的信息：共有57 651个单词，但只有4731个不同的单词。在第一个翻译程序之后，每个单词有4.3个字母。输出表明，最常见的单词是“the”，占了文件的6%。6个最常见的单词占了文件的18%。对英语中最常见的100个单词做专门处理也许还能提高速度。试试看从这些计数中找出其他有趣的表面规律。
跟许多UNIX用户一样，我过去也用手工监视管道的性能，利用单词计数（wc）命令来统计文件，用time命令来统计进程。“管道性能监视工具”让这个任务自动化了。用管道和一些输入文件的名称作为输入，产生性能监视结果作为输出。2个小时和50行代码就足以建立这个性能监视工具。下一节详细阐述这个话题。
4 开发性能监视工具
开发一个真正的性能监视工具是件困难的事情。Peter Weinberger开发了C行计数性能监视工具，我们前面看到的输出就是这个工具产生的。他在几个月时间内断断续续干了好几周才完成这个项目。本节描述如何更容易地开发一个简化版本。
Dick Sites声称他的朋友“在某个周末实现了语句计数”。我觉得这简直难以置信，于是我决定要试着为附录A描述的Awk语言（这种语言还没有性能监视工具）开发一个性能监视工具。几小时后，当我运行程序P6的Awk版本时，我的性能监视工具生成了如下输出。
程序P6及性能监视工具生成的输出
BEGIN { <<<1>>>
n = 1000
x[0] = 2; xc = 1
print 2
for (i = 3; i <= n; i++) { <<<998>>>
if (prime(i)) { <<<167>>>
print i
}
}
exit
}
function prime(n, i) { <<<998>>>
for (i=0; x[i]*x[i]<=n; i++) { <<<2801>>>
if (n % x[i] == 0) { <<<831>>>
return 0
}
}
{ <<<167>>> }
x[xc++] = n
return 1
}
在左花括号后尖括号内的数显示该语句块被执行了多少次。幸运的是，这些计数与C行计数器产生的计数一样。
我的性能监视工具包含两个5行的Awk程序。第一个程序读Awk源程序并且写一个新程序，其中在每个语句块开始的地方给不同的计数器加1；而在执行结束时，一个新的END动作（见附录A）把所有计数写入一个文件。当这样得出的程序运行时，就生成一个计数文件。第二个程序读出这些计数，把这些计数合并到源文本中。带性能监视的程序大约比原来的程序慢25%，而且并不是所有的Awk程序都能正确处理——为了监视几个程序的性能，我不得不做出整行（one-line）的修改。但对于所有这些缺点来说，搭起一个能运行的性能监视工具，花几小时并不算什么大投入。
人们实现过一些快速性能监视工具，但鲜见报道。下面举几个例子。
在1983年8月的 BYTE 杂志上，Leas和Wintz描述了一个性能监视工具，用一个20行的6 800汇编语言程序来实现。
贝尔实验室的Howard Trickey在一小时内用Lisp实现了函数计数，办法是修改defun，在进入每个函数时给计数器加1。
1978年，Rob Pike用20行Fortran程序实现了一个时间性能监视工具。在CALL PROFIL(10)之后，后续的CPU时间被计入计数器10。
在这些系统和许多其他系统上，在一晚上写出一个性能监视工具是可能的。在你第一次使用所得到的性能监视工具时，这个工具轻易就能节省超过一个晚上的工作量。
5 原理
本文只浮光掠影地介绍了性能监视。我介绍了最基础的内容，忽略了搜集数据的其他方式（比如硬件监视器）和其他显示方式（比如动画系统）。本文所要传达的信息同样是基本的。
- 使用性能监视工具。让本月成为性能监视工具月。请在随后几周内至少监视一个程序片段的性能，并且鼓励你的伙伴们也这样做。记住，当一个程序员屈尊来帮助一个小程序时，并不总是高瞻远瞩的。
- 开发性能监视工具。如果你还没有方便的性能监视工具，就自造一个吧。大多数系统都提供基本的性能监视操作。20世纪60年代不得不观察控制台灯光来获得信息的程序员，现在可从个人工作站的图形窗口获得同样的信息。一个小程序通常足以把系统的命令特性包装成方便的工具。
本文节选自《编程珠玑（续）（修订版）》
