[Omaha.pm] [patch] Devel::Timer

["Jay Hannah" <jhannah@omnihotels.com>]

Hi Jason --

I just discovered Devel::Timer. I love it! Thanks for putting it on
CPAN!

I'm trying to use it for timing some critical junctures in some of my
enormous programs. The problem I was having is that my combinations of
marks are hit dozens or hundreds of times as the program interates. That
makes the report() output pages and pages long, and not very useful.

So I added a couple new report() features. :)

Here's a sample program for you to see what my patch does:

---
$ cat j.pl
#!/usr/bin/perl

use Devel::Timer;

my $t = Devel::Timer->new();
for (1..3) {
   $t->mark("something begin");
   sleep $_;
   $t->mark("something end");
}

sleep 1;
$t->mark("END");

print "\$t->report;\n\n";
$t->report;
print "\n\n";

print "\$t->report(collapse => 1);\n\n";
$t->report(collapse => 1);
print "\n\n";

print "\$t->report(collapse => 1, sort_by => 'count');\n\n";
$t->report(collapse => 1, sort_by => 'count');
---

Simple enough. The standard report() looks like this:

$t->report;

Devel::Timer Report -- Total time: 7.0028 secs
Interval  Time    Percent
----------------------------------------------
05 -> 06  3.0006  42.85%  something begin -> something end
03 -> 04  2.0007  28.57%  something begin -> something end
06 -> 07  1.0009  14.29%  something end -> END
01 -> 02  1.0004  14.29%  something begin -> something end
00 -> 01  0.0000   0.00%  INIT -> something begin
04 -> 05  0.0000   0.00%  something end -> something begin
02 -> 03  0.0000   0.00%  something end -> something begin

Which is great for small or non-iterative programs, but if there's
hundreds of loops of "something begin -> something end" the report gets
very painful very quickly. :)

So I wrote a collapse feature that people can activate if they want to:

$t->report(collapse => 1);

Devel::Timer Report -- Total time: 7.0028 secs
Count     Time    Percent
----------------------------------------------
       3  6.0018  85.71%  something begin -> something end
       1  1.0009  14.29%  something end -> END
       2  0.0001   0.00%  something end -> something begin
       1  0.0000   0.00%  INIT -> something begin

The stats for all combinations of labels are added together. 

I also added a sort_by feature. By default the report is sorted by total
time spent (like the default report()), but you can sort by count
instead if you want:

$t->report(collapse => 1, sort_by => 'count');

Devel::Timer Report -- Total time: 7.0028 secs
Count     Time    Percent
----------------------------------------------
       3  6.0018  85.71%  something begin -> something end
       2  0.0001   0.00%  something end -> something begin
       1  0.0000   0.00%  INIT -> something begin
       1  1.0009  14.29%  something end -> END

Pretty neat huh? Awfully handy for me anyway. :)

I didn't write any POD yet because I thought you might want to change
the interface.

My patch is below. Thoughts?

Thanks again,

j




$ diff -ruN Timer_orig.pm Timer.pm
--- Timer_orig.pm       2006-05-10 15:43:03.000000000 -0500
+++ Timer.pm    2006-05-11 11:10:36.000000000 -0500
@@ -76,7 +76,7 @@

 sub report
 {
-    my $self = shift;
+    my ($self, %args) = @_;

     ## calculate total time (start time vs last time)

@@ -84,9 +84,31 @@

     $self->print("\n");
     $self->print(ref($self) . " Report -- Total time: " .
sprintf("%.4f", $total_time) . " secs");
+
+    if ($args{collapse})
+    {
+       $self->calculate_collapsed;
+
+       $self->print("Count     Time    Percent");
+       $self->print("----------------------------------------------");
+
+       my $c = $self->{collapsed};
+       my $sort_by = $args{sort_by} || "time";
+       my @labels = sort { $c->{$b}->{$sort_by} <=>
$c->{$a}->{$sort_by} } keys %$c;
+       foreach (@labels)
+       {
+           my $count = $c->{$_}->{count};
+           my $time = $c->{$_}->{time};
+           my $msg = sprintf("%8s  %.4f  %5.2f%%  %s",
+               ($count, $time, (($time/$total_time)*100), $_));
+           $self->print($msg);
+       }
+       return 1;
+    }
+
     $self->print("Interval  Time    Percent");
     $self->print("----------------------------------------------");
-
+
     ## sort interval structure based on value

     @{$self->{intervals}} = sort { $b->{value} <=> $a->{value} }
@{$self->{intervals}};
@@ -111,6 +133,23 @@
     }
 }

+
+sub calculate_collapsed
+{
+    my ($self) = @_;
+
+    my %collapsed;
+    foreach my $i (0 .. $self->{count} - 2)
+    {
+        my $label = $self->{label}->{$i} . ' -> ' . $self->{label}->{$i
+ 1};
+        my $time = Time::HiRes::tv_interval($self->{times}->[$i],
$self->{times}->[$i + 1]);
+        $collapsed{$label}{time} += $time;
+        $collapsed{$label}{count}++;
+    }
+    $self->{collapsed} = \%collapsed;
+}
+
+
 ## output methods
 ## note: if you want to send output to somewhere other than stderr,
 ##       you can override the print() method below.  The initialize()