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__ |