| line |
stmt |
bran |
cond |
sub |
pod |
time |
code |
|
1
|
|
|
|
|
|
|
package Time::Checkpoint::Sequential; |
|
2
|
|
|
|
|
|
|
# ABSTRACT: Report timing between checkpoints in code |
|
3
|
1
|
|
|
1
|
|
292271
|
use strict; |
|
|
1
|
|
|
|
|
4
|
|
|
|
1
|
|
|
|
|
49
|
|
|
4
|
1
|
|
|
1
|
|
7
|
use warnings; |
|
|
1
|
|
|
|
|
3
|
|
|
|
1
|
|
|
|
|
72
|
|
|
5
|
|
|
|
|
|
|
|
|
6
|
|
|
|
|
|
|
our $VERSION = '0.002'; |
|
7
|
|
|
|
|
|
|
|
|
8
|
|
|
|
|
|
|
=head1 NAME |
|
9
|
|
|
|
|
|
|
|
|
10
|
|
|
|
|
|
|
Time::Checkpoint::Sequential - record time taken between points in code |
|
11
|
|
|
|
|
|
|
|
|
12
|
|
|
|
|
|
|
=head1 VERSION |
|
13
|
|
|
|
|
|
|
|
|
14
|
|
|
|
|
|
|
version 0.002 |
|
15
|
|
|
|
|
|
|
|
|
16
|
|
|
|
|
|
|
=head1 SYNOPSIS |
|
17
|
|
|
|
|
|
|
|
|
18
|
|
|
|
|
|
|
use Time::Checkpoint::Sequential; |
|
19
|
|
|
|
|
|
|
my $checkpoint = Time::Checkpoint::Sequential->new(report_on_destroy => 0); |
|
20
|
|
|
|
|
|
|
slow_operation(); |
|
21
|
|
|
|
|
|
|
$checkpoint->mark('Perform some operation'); |
|
22
|
|
|
|
|
|
|
another_operation(); |
|
23
|
|
|
|
|
|
|
$checkpoint->mark('Do something else'); |
|
24
|
|
|
|
|
|
|
$checkpoint->report(sub { warn " Timing info: @_\n"; }); |
|
25
|
|
|
|
|
|
|
|
|
26
|
|
|
|
|
|
|
=head1 DESCRIPTION |
|
27
|
|
|
|
|
|
|
|
|
28
|
|
|
|
|
|
|
=cut |
|
29
|
|
|
|
|
|
|
|
|
30
|
1
|
|
|
1
|
|
1037
|
use Time::HiRes (); |
|
|
1
|
|
|
|
|
2139
|
|
|
|
1
|
|
|
|
|
32
|
|
|
31
|
1
|
|
|
1
|
|
8
|
use List::Util (); |
|
|
1
|
|
|
|
|
3
|
|
|
|
1
|
|
|
|
|
427
|
|
|
32
|
|
|
|
|
|
|
|
|
33
|
|
|
|
|
|
|
=head1 METHODS |
|
34
|
|
|
|
|
|
|
|
|
35
|
|
|
|
|
|
|
=cut |
|
36
|
|
|
|
|
|
|
|
|
37
|
|
|
|
|
|
|
=head2 new |
|
38
|
|
|
|
|
|
|
|
|
39
|
|
|
|
|
|
|
Instantiate the object. |
|
40
|
|
|
|
|
|
|
|
|
41
|
|
|
|
|
|
|
Accepts the following named parameter: |
|
42
|
|
|
|
|
|
|
|
|
43
|
|
|
|
|
|
|
=over 4 |
|
44
|
|
|
|
|
|
|
|
|
45
|
|
|
|
|
|
|
=item * report_on_destroy - if true, will call L when destroyed, default is true |
|
46
|
|
|
|
|
|
|
|
|
47
|
|
|
|
|
|
|
=back |
|
48
|
|
|
|
|
|
|
|
|
49
|
|
|
|
|
|
|
=cut |
|
50
|
|
|
|
|
|
|
|
|
51
|
|
|
|
|
|
|
sub new { |
|
52
|
0
|
|
|
0
|
1
|
|
my $class = shift; |
|
53
|
0
|
|
|
|
|
|
my %args = @_; |
|
54
|
0
|
|
|
|
|
|
bless { |
|
55
|
|
|
|
|
|
|
report_on_destroy => 1, |
|
56
|
|
|
|
|
|
|
items => [], |
|
57
|
|
|
|
|
|
|
'last' => Time::HiRes::time, |
|
58
|
|
|
|
|
|
|
maxlen => 0, |
|
59
|
|
|
|
|
|
|
%args, |
|
60
|
|
|
|
|
|
|
}, $class; |
|
61
|
|
|
|
|
|
|
} |
|
62
|
|
|
|
|
|
|
|
|
63
|
|
|
|
|
|
|
=head2 mark |
|
64
|
|
|
|
|
|
|
|
|
65
|
|
|
|
|
|
|
Records this event. Takes a scalar which will be used as the name for this event. |
|
66
|
|
|
|
|
|
|
|
|
67
|
|
|
|
|
|
|
=cut |
|
68
|
|
|
|
|
|
|
|
|
69
|
|
|
|
|
|
|
sub mark { |
|
70
|
0
|
|
|
0
|
1
|
|
my $self = shift; |
|
71
|
0
|
|
|
|
|
|
my $name = shift; |
|
72
|
0
|
|
|
|
|
|
my $now = Time::HiRes::time; |
|
73
|
|
|
|
|
|
|
|
|
74
|
|
|
|
|
|
|
# Record name and number of milliseconds since last event |
|
75
|
0
|
|
|
|
|
|
push @{$self->{items}}, [ $name, 1000.0 * ($now - $self->{last}) ]; |
|
|
0
|
|
|
|
|
|
|
|
76
|
0
|
|
|
|
|
|
$self->{maxlen} = List::Util::max(length($name), $self->{maxlen}); |
|
77
|
0
|
|
|
|
|
|
$self->{last} = $now; |
|
78
|
0
|
|
|
|
|
|
return $self; |
|
79
|
|
|
|
|
|
|
} |
|
80
|
|
|
|
|
|
|
|
|
81
|
|
|
|
|
|
|
=head2 reset_timer |
|
82
|
|
|
|
|
|
|
|
|
83
|
|
|
|
|
|
|
Updates the timer so that the next recorded event will be from now, rather than the last time. |
|
84
|
|
|
|
|
|
|
|
|
85
|
|
|
|
|
|
|
=cut |
|
86
|
|
|
|
|
|
|
|
|
87
|
|
|
|
|
|
|
sub reset_timer { |
|
88
|
0
|
|
|
0
|
1
|
|
my $self = shift; |
|
89
|
0
|
|
|
|
|
|
my $now = Time::HiRes::time; |
|
90
|
0
|
|
|
|
|
|
$self->{last} = $now; |
|
91
|
0
|
|
|
|
|
|
return $self; |
|
92
|
|
|
|
|
|
|
} |
|
93
|
|
|
|
|
|
|
|
|
94
|
|
|
|
|
|
|
=head2 report |
|
95
|
|
|
|
|
|
|
|
|
96
|
|
|
|
|
|
|
Generates a report. Pass a code ref to customise the output (will be called for each item and then a final |
|
97
|
|
|
|
|
|
|
time for the total). |
|
98
|
|
|
|
|
|
|
|
|
99
|
|
|
|
|
|
|
=cut |
|
100
|
|
|
|
|
|
|
|
|
101
|
|
|
|
|
|
|
sub report { |
|
102
|
0
|
|
|
0
|
1
|
|
my $self = shift; |
|
103
|
0
|
|
0
|
0
|
|
|
my $code = shift || sub { print STDERR " @_\n"; }; |
|
|
0
|
|
|
|
|
|
|
|
104
|
|
|
|
|
|
|
|
|
105
|
0
|
|
|
|
|
|
my $l = $self->{maxlen}; |
|
106
|
0
|
|
|
|
|
|
my $total = 0; |
|
107
|
0
|
|
|
|
|
|
foreach my $item (@{$self->{items}}) { |
|
|
0
|
|
|
|
|
|
|
|
108
|
0
|
|
|
|
|
|
$code->(sprintf "%-$l.${l}s %9.3fms", @$item); |
|
109
|
0
|
|
|
|
|
|
$total += $item->[1]; |
|
110
|
|
|
|
|
|
|
} |
|
111
|
0
|
|
|
|
|
|
$code->(sprintf "%-$l.${l}s %9.3fms", "Total:", $total); |
|
112
|
|
|
|
|
|
|
} |
|
113
|
|
|
|
|
|
|
|
|
114
|
|
|
|
|
|
|
=head2 DESTROY |
|
115
|
|
|
|
|
|
|
|
|
116
|
|
|
|
|
|
|
Shows report when this object goes out of scope, unless disabled in the constructor. |
|
117
|
|
|
|
|
|
|
|
|
118
|
|
|
|
|
|
|
=cut |
|
119
|
|
|
|
|
|
|
|
|
120
|
|
|
|
|
|
|
sub DESTROY { |
|
121
|
0
|
|
|
0
|
|
|
my $self = shift; |
|
122
|
0
|
0
|
|
|
|
|
$self->report if $self->{report_on_destroy}; |
|
123
|
|
|
|
|
|
|
} |
|
124
|
|
|
|
|
|
|
|
|
125
|
|
|
|
|
|
|
1; |
|
126
|
|
|
|
|
|
|
|
|
127
|
|
|
|
|
|
|
__END__ |