line |
stmt |
bran |
cond |
sub |
pod |
time |
code |
1
|
|
|
|
|
|
|
package RHP::Timer; |
2
|
|
|
|
|
|
|
|
3
|
1
|
|
|
1
|
|
21601
|
use strict; |
|
1
|
|
|
|
|
2
|
|
|
1
|
|
|
|
|
34
|
|
4
|
1
|
|
|
1
|
|
5
|
use warnings; |
|
1
|
|
|
|
|
1
|
|
|
1
|
|
|
|
|
31
|
|
5
|
|
|
|
|
|
|
|
6
|
|
|
|
|
|
|
=head1 NAME |
7
|
|
|
|
|
|
|
|
8
|
|
|
|
|
|
|
RHP::Timer - A high resolution timer abstraction |
9
|
|
|
|
|
|
|
|
10
|
|
|
|
|
|
|
=head1 SYNOPSIS |
11
|
|
|
|
|
|
|
|
12
|
|
|
|
|
|
|
use RHP::Timer (); |
13
|
|
|
|
|
|
|
use My::Logger (); |
14
|
|
|
|
|
|
|
|
15
|
|
|
|
|
|
|
$logger = My::Logger->new; |
16
|
|
|
|
|
|
|
$timer = RHP::Timer->new(); |
17
|
|
|
|
|
|
|
|
18
|
|
|
|
|
|
|
# timing data from the point of the caller |
19
|
|
|
|
|
|
|
$timer->start('fizzbin'); |
20
|
|
|
|
|
|
|
fizzbin(); # how fast is fizzbin? |
21
|
|
|
|
|
|
|
$logger->info( |
22
|
|
|
|
|
|
|
sprintf("Timing caller: %s %s %d, timer_name: %s, time: %s", |
23
|
|
|
|
|
|
|
@{$timer->checkpoint})); |
24
|
|
|
|
|
|
|
|
25
|
|
|
|
|
|
|
# or simpler |
26
|
|
|
|
|
|
|
$timer->start('foobin'); |
27
|
|
|
|
|
|
|
foobin(); |
28
|
|
|
|
|
|
|
$logger->info("pid $$ timer " . $timer->current . |
29
|
|
|
|
|
|
|
" took " . $timer->stop . " seconds"); |
30
|
|
|
|
|
|
|
|
31
|
|
|
|
|
|
|
# what was the last timing block? |
32
|
|
|
|
|
|
|
$logger->info("Last timing block " . $timer->current . |
33
|
|
|
|
|
|
|
" took " . $timer->last_interval . " seconds"); |
34
|
|
|
|
|
|
|
|
35
|
|
|
|
|
|
|
=head1 DESCRIPTION |
36
|
|
|
|
|
|
|
|
37
|
|
|
|
|
|
|
RHP::Timer is a wrapper around Time::HiRes. I wrote it because I |
38
|
|
|
|
|
|
|
needed some simple abstractions for timing programs to |
39
|
|
|
|
|
|
|
determine bottlenecks in running programs. |
40
|
|
|
|
|
|
|
|
41
|
|
|
|
|
|
|
The goals of RHP::Timer is to be easy to use, accurate, and simple. |
42
|
|
|
|
|
|
|
|
43
|
|
|
|
|
|
|
=cut |
44
|
|
|
|
|
|
|
|
45
|
1
|
|
|
1
|
|
875
|
use Time::HiRes (); |
|
1
|
|
|
|
|
1703
|
|
|
1
|
|
|
|
|
126
|
|
46
|
|
|
|
|
|
|
|
47
|
|
|
|
|
|
|
our $VERSION = 0.1; |
48
|
|
|
|
|
|
|
|
49
|
|
|
|
|
|
|
=head1 METHODS |
50
|
|
|
|
|
|
|
|
51
|
|
|
|
|
|
|
=over 4 |
52
|
|
|
|
|
|
|
|
53
|
|
|
|
|
|
|
=item new() |
54
|
|
|
|
|
|
|
|
55
|
|
|
|
|
|
|
$timer = RHP::Timer->new(); |
56
|
|
|
|
|
|
|
|
57
|
|
|
|
|
|
|
Constructor which takes no arguments and returns a timer object |
58
|
|
|
|
|
|
|
|
59
|
|
|
|
|
|
|
=cut |
60
|
|
|
|
|
|
|
|
61
|
|
|
|
|
|
|
sub new { |
62
|
2
|
|
|
2
|
1
|
936
|
my ($class) = @_; |
63
|
2
|
|
|
|
|
5
|
my $self = {}; |
64
|
2
|
|
|
|
|
7
|
bless $self, $class; |
65
|
2
|
|
|
|
|
7
|
return $self; |
66
|
|
|
|
|
|
|
} |
67
|
|
|
|
|
|
|
|
68
|
|
|
|
|
|
|
=item start() |
69
|
|
|
|
|
|
|
|
70
|
|
|
|
|
|
|
$timer->start('fizzbin'); |
71
|
|
|
|
|
|
|
|
72
|
|
|
|
|
|
|
Starts the timer for 'fizzbin' |
73
|
|
|
|
|
|
|
|
74
|
|
|
|
|
|
|
=cut |
75
|
|
|
|
|
|
|
|
76
|
|
|
|
|
|
|
sub start { |
77
|
3
|
|
|
3
|
1
|
396
|
my ($self, $name) = @_; |
78
|
3
|
|
|
|
|
33
|
$self->{$name}->{_start} = [Time::HiRes::gettimeofday]; |
79
|
3
|
|
|
|
|
6
|
$self->{_current} = $name; |
80
|
3
|
|
|
|
|
9
|
return 1; |
81
|
|
|
|
|
|
|
} |
82
|
|
|
|
|
|
|
|
83
|
|
|
|
|
|
|
=item stop() |
84
|
|
|
|
|
|
|
|
85
|
|
|
|
|
|
|
$interval = $timer->stop; |
86
|
|
|
|
|
|
|
|
87
|
|
|
|
|
|
|
Stops the last timer started, and returns the number of seconds between |
88
|
|
|
|
|
|
|
start and stop. |
89
|
|
|
|
|
|
|
|
90
|
|
|
|
|
|
|
=cut |
91
|
|
|
|
|
|
|
|
92
|
|
|
|
|
|
|
sub stop { |
93
|
4
|
|
|
4
|
1
|
1000144
|
my ($self) = @_; |
94
|
1
|
|
|
1
|
|
5
|
no strict 'refs'; |
|
1
|
|
|
|
|
1
|
|
|
1
|
|
|
|
|
180
|
|
95
|
4
|
|
|
|
|
62
|
$self->{$self->{_current}}->{_stop} = [Time::HiRes::gettimeofday]; |
96
|
4
|
|
|
|
|
31
|
$self->{$self->{_current}}->{interval} = |
97
|
|
|
|
|
|
|
Time::HiRes::tv_interval($self->{$self->{_current}}->{_start}, |
98
|
|
|
|
|
|
|
$self->{$self->{_current}}->{_stop}); |
99
|
4
|
|
|
|
|
71
|
return $self->{$self->{_current}}->{interval}; |
100
|
|
|
|
|
|
|
} |
101
|
|
|
|
|
|
|
|
102
|
|
|
|
|
|
|
=item current() |
103
|
|
|
|
|
|
|
|
104
|
|
|
|
|
|
|
$timer_name = $timer->current(); |
105
|
|
|
|
|
|
|
# $timer_name is 'fizzbin' from previous pod |
106
|
|
|
|
|
|
|
|
107
|
|
|
|
|
|
|
Returns the name of the most recent timer started. |
108
|
|
|
|
|
|
|
|
109
|
|
|
|
|
|
|
=cut |
110
|
|
|
|
|
|
|
|
111
|
|
|
|
|
|
|
sub current { |
112
|
2
|
|
|
2
|
1
|
10
|
my $self = shift; |
113
|
2
|
|
|
|
|
23
|
return $self->{_current}; |
114
|
|
|
|
|
|
|
} |
115
|
|
|
|
|
|
|
|
116
|
|
|
|
|
|
|
=item checkpoint() |
117
|
|
|
|
|
|
|
|
118
|
|
|
|
|
|
|
[ caller(), $timer_name, $interval ] = $timer->checkpoint(); |
119
|
|
|
|
|
|
|
|
120
|
|
|
|
|
|
|
Stops the current timer and returns an array reference containing caller() |
121
|
|
|
|
|
|
|
information, the name of the timer stopped, and the interval of the last |
122
|
|
|
|
|
|
|
timing run. Useful for passing to a logfile in sprintf or other format. |
123
|
|
|
|
|
|
|
|
124
|
|
|
|
|
|
|
=cut |
125
|
|
|
|
|
|
|
|
126
|
|
|
|
|
|
|
sub checkpoint { |
127
|
1
|
|
|
1
|
1
|
5
|
my $self = shift; |
128
|
1
|
|
|
|
|
10
|
my $stop = $self->stop; |
129
|
1
|
|
|
|
|
11
|
my @summary = ( caller, $self->current, $self->stop); |
130
|
1
|
|
|
|
|
8
|
return \@summary; |
131
|
|
|
|
|
|
|
} |
132
|
|
|
|
|
|
|
|
133
|
|
|
|
|
|
|
=item last_interval() |
134
|
|
|
|
|
|
|
|
135
|
|
|
|
|
|
|
$last_interval = $timer->last_interval; |
136
|
|
|
|
|
|
|
|
137
|
|
|
|
|
|
|
Returns the last timing interval recorded by the timer object. |
138
|
|
|
|
|
|
|
|
139
|
|
|
|
|
|
|
=cut |
140
|
|
|
|
|
|
|
|
141
|
|
|
|
|
|
|
sub last_interval { |
142
|
2
|
|
|
2
|
1
|
3515
|
my $self = shift; |
143
|
2
|
|
|
|
|
18
|
return $self->{$self->{_current}}->{interval}; |
144
|
|
|
|
|
|
|
} |
145
|
|
|
|
|
|
|
|
146
|
|
|
|
|
|
|
=pod |
147
|
|
|
|
|
|
|
|
148
|
|
|
|
|
|
|
=back |
149
|
|
|
|
|
|
|
|
150
|
|
|
|
|
|
|
=cut |
151
|
|
|
|
|
|
|
|
152
|
|
|
|
|
|
|
1; |
153
|
|
|
|
|
|
|
|
154
|
|
|
|
|
|
|
__END__ |