Perl使用DProf测定程序执行效率

代码写多了，程序就会变得臃肿；程序臃肿了，就会变慢。这时提高代码执行效率就非常重要了。但是，代码优化并不是几条best practice就能完成的。那些无关痛痒的空间分配、减少复制等优化措施，虽然有效，但却微乎其微。优化的关键，是要找出瓶颈并解决之，这样才能以最小的代价获得最佳的效果。

这就用到Perl的一个强大的工具：DProf。它可以测定程序执行的每个函数所花费的时间，通过它，你可以迅速找到瓶颈在什么地方，再对症下药。

最近我做的一次性能分析是这样的。我们的系统在某种条件下发送邮件时特别慢，甚至等待十几分钟也无法结束。究竟问题出在哪里却不得而知。于是DProf上场了。

首先写了个脚本，专门调用发送邮件的功能，排除其他功能的影响。然后运行命令：

$ perl -d:DProf ./sendmail.pl

运行结束之后，会在当前目录下生成一个tmon.out文件。使用dprofpp即可查看统计信息：

$ dprofpp
Total Elapsed Time = 19.70195 Seconds
 User+System Time = 18.52195 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 83.5   15.46 15.770     11   1.4059 1.4337  Foo::Bar::crypt
 9.34   1.730  1.730      2   0.8650 0.8650  Net::Cmd::datasend
 1.24   0.230  0.305  17459   0.0000 0.0000  Crypt::Blowfish::encrypt
 0.70   0.129  0.818     36   0.0036 0.0227  base::import
 0.59   0.110  0.709     24   0.0046 0.0296  Foo::Bar::FooBarList::BEGIN
 0.44   0.082  0.082   9108   0.0000 0.0000  IO::Wrap::read
 0.40   0.075  0.075  17647   0.0000 0.0000  Crypt::Blowfish::crypt
 0.27   0.050  0.887      7   0.0071 0.1268  main::BEGIN

统计信息的意思分别是：

• ExclSec: 函数自身的执行时间（不包括函数调用的其他函数）
• CumulS: 函数的执行时间（包括函数调用的其他函数）
• #Calls: 调用次数
• sec/call: ExceSec/#Calls
• Csec/c: CumulS/#Calls
• Name: 函数名称

从上面的统计信息中可以看出，Foo::Bar::crypt占用了最多的时间(83.5%)。而且更为重要的信息是，CumulS - ExclSec = 15.770 - 15.46 = 0.31，也就是说，绝大部分时间都耗在了 Foo::Bar::crypt 函数本身，而不是它调用的其他函数。这样，只需针对Foo::Bar::crypt函数进行分析就可以了。

还可以使用另一个性能测试工具Devel::SmallProf。