使用Devel::Timer识别慢代码

2016年8月17日由David Farrell编写

程序速度是编程中的一个重要因素。没有人希望自己的程序执行速度变慢。作为一种通用编程语言，Perl通常足够快，可以处理大多数事情，如果不快，我们有一些优秀的工具可以帮助我们使其更快。我们可以使用Benchmark模块比较代码和Devel::NYTProf来产生我们程序的详细分析。

本文介绍了Devel::Timer，这是一个我喜欢在优化现有子程序时使用的模块，并且不确定子程序中每个语句的执行时间。它很容易设置，所以如果你以前没有使用过它，一旦你阅读了这篇文章，你将拥有另一个优化代码的工具。

使用Devel::Timer获取时间报告

假设我有一个非常慢的子程序，但我不确定是什么让它变慢。这个（虚构的）子程序看起来像这样

sub foo {
  my $args = shift;

  die 'foo() requires an hashref of args'
    unless $args && ref $args eq 'HASH';

  my %parsed_args = validate_args($args);

  my $user        = find_user($parsed_args{username});

  my $location    = get_location($parsed_args{req_address});

  my $bar         = register_request($user, $location);

  return $bar;
}

我可以用Devel::Timer来计时子程序中的每个语句，并告诉我每个语句花费了多少时间

use Devel::Timer;

sub foo {
  my $args = shift;
  my $timer = Devel::Timer->new();

  die 'foo() requires an hashref of args'
    unless $args && ref $args eq 'HASH';
  $timer->mark('check $args is hashref');

  my %parsed_args = validate_args($args);
  $timer->mark('validate_args()');

  my $user        = find_user($parsed_args{username});
  $timer->mark('find_user()');

  my $location    = get_location($parsed_args{req_address});
  $timer->mark('get_location()');

  my $bar         = register_request($user, $location);
  $timer->mark('register_request()');

  $timer->report();
  return $bar;
}

我已经更新了代码，导入了Devel::Timer并构造了一个新的$timer对象。在我想计时每个语句之后，我调用mark方法，它将一个条目添加到计时器中，就像在秒表中记录分段时间。最后，我调用report，它会打印出一个表格，列出每次调用mark之间花费的时间。

Devel::Timer Report -- Total time: 0.0515 secs
Interval  Time    Percent
----------------------------------------------
02 -> 03  0.0328  63.68%  validate_args() -> find_user()
04 -> 05  0.0095  18.44%  get_location() -> register_request()
03 -> 04  0.0081  15.72%  find_user() -> get_location()
06 -> 07  0.0010   0.19%  register_request() -> END
01 -> 02  0.0001   0.00%  check $args is hashref -> validate_args()
00 -> 01  0.0000   0.00%  INIT -> check $args is hashref

默认情况下，表格按持续时间降序打印。输出显示该子程序执行了515毫秒，从validate_args()标记到find_user()标记的持续时间占了运行时间的63.68%。所以如果我要重构这个子程序，我会从find_user()函数开始。

在我的经验中，这是典型的时间分布。很难找到一个子程序中的每个语句花费相同的时间。通常只有一个或两个原因，如果你能重构那些，子程序的运行时间可以改善一个数量级或更多。