line |
stmt |
code |
1
|
|
|
2
|
|
use Mojo::Base -strict, -signatures; |
3
|
74
|
|
|
74
|
|
|
74
|
|
4
|
|
our $VERSION = '0.05'; |
5
|
|
use Time::HiRes; |
6
|
74
|
|
|
74
|
|
|
74
|
|
7
|
|
=head1 NAME |
8
|
|
|
9
|
|
Benchmark::Stopwatch - simple timing of stages of your code. |
10
|
|
|
11
|
|
=head1 SYNOPSIS |
12
|
|
|
13
|
|
use Benchmark::Stopwatch; |
14
|
|
my $stopwatch = Benchmark::Stopwatch->new->start; |
15
|
|
|
16
|
|
# ... code that reads from database ... |
17
|
|
$stopwatch->lap('read from database'); |
18
|
|
|
19
|
|
# ... code that writes to disk ... |
20
|
|
$stopwatch->lap('write to disk'); |
21
|
|
|
22
|
|
print $stopwatch->stop->summary; |
23
|
|
|
24
|
|
# NAME TIME CUMULATIVE PERCENTAGE |
25
|
|
# read from database 0.123 0.123 34.462% |
26
|
|
# write to disk 0.234 0.357 65.530% |
27
|
|
# _stop_ 0.000 0.357 0.008% |
28
|
|
|
29
|
|
=head1 DESCRIPTION |
30
|
|
|
31
|
|
The other benchmark modules provide excellent timing for specific parts of |
32
|
|
your code. This module aims to allow you to easily time the progression of |
33
|
|
your code. |
34
|
|
|
35
|
|
The stopwatch analogy is that at some point you get a C<new> stopwatch and |
36
|
|
C<start> timing. Then you note certain events using C<lap>. Finally you |
37
|
|
C<stop> the watch and then print out a C<summary>. |
38
|
|
|
39
|
|
The summary shows all the events in order, what time they occurred at, how long |
40
|
|
since the last lap and the percentage of the total time. Hopefully this will |
41
|
|
give you a good idea of where your code is spending most of its time. |
42
|
|
|
43
|
|
The times are all wallclock times in fractional seconds. |
44
|
|
|
45
|
|
That's it. |
46
|
|
|
47
|
|
=head1 METHODS |
48
|
|
|
49
|
|
=head2 new |
50
|
|
|
51
|
|
my $stopwatch = Benchmark::Stopwatch->new; |
52
|
|
|
53
|
|
Creates a new stopwatch. |
54
|
|
|
55
|
|
=cut |
56
|
|
|
57
|
|
my $self = {}; |
58
|
411
|
|
|
411
|
|
|
411
|
|
59
|
411
|
$self->{events} = []; |
60
|
|
$self->{_time} = sub { Time::HiRes::time() }; |
61
|
411
|
$self->{length} = 26; |
62
|
411
|
|
|
1849
|
|
63
|
411
|
return bless $self, $class; |
64
|
|
} |
65
|
411
|
|
66
|
|
=head2 start |
67
|
|
|
68
|
|
$stopwatch = $stopwatch->start; |
69
|
|
|
70
|
|
Starts the stopwatch. Returns a reference to the stopwatch so that you can |
71
|
|
chain. |
72
|
|
|
73
|
|
=cut |
74
|
|
|
75
|
|
$self->{start} = $self->time; |
76
|
|
return $self; |
77
|
411
|
} |
|
411
|
|
|
411
|
|
78
|
411
|
|
79
|
411
|
=head2 lap |
80
|
|
|
81
|
|
$stopwatch = $stopwatch->lap( 'name of event' ); |
82
|
|
|
83
|
|
Notes down the time at which an event occurs. This event will later appear in |
84
|
|
the summary. |
85
|
|
|
86
|
|
=cut |
87
|
|
|
88
|
|
my $time = $self->time; |
89
|
|
$self->{length} = length $name // $self->{length}; |
90
|
|
push @{$self->{events}}, {name => $name, time => $time}; |
91
|
1033
|
return $self; |
|
1033
|
|
|
1033
|
|
|
1033
|
|
92
|
1033
|
} |
93
|
1033
|
|
94
|
1033
|
=head2 stop |
|
1033
|
|
95
|
1033
|
|
96
|
|
$stopwatch = $stopwatch->stop; |
97
|
|
|
98
|
|
Stops the stopwatch. Returns a reference to the stopwatch so you can chain. |
99
|
|
|
100
|
|
=cut |
101
|
|
|
102
|
|
$self->{stop} = $self->time; |
103
|
|
return $self; |
104
|
|
} |
105
|
|
|
106
|
405
|
=head2 total_time |
|
405
|
|
|
405
|
|
107
|
405
|
|
108
|
405
|
my $time_in_seconds = $stopwatch->total_time; |
109
|
|
|
110
|
|
Returns the time that the stopwatch ran for in fractional seconds. If the |
111
|
|
stopwatch has not been stopped yet then it returns time it has been running |
112
|
|
for. |
113
|
|
|
114
|
|
=cut |
115
|
|
|
116
|
|
# Get the stop time or now if missing. |
117
|
|
my $stop = $self->{stop} || $self->time; |
118
|
|
|
119
|
|
return $stop - $self->{start}; |
120
|
|
} |
121
|
71
|
|
|
71
|
|
|
71
|
|
122
|
|
=head2 summary |
123
|
71
|
|
124
|
|
my $summary_text = $stopwatch->summary; |
125
|
71
|
|
126
|
|
Returns text summarizing the events that occurred. Example output from a script |
127
|
|
that fetches the homepages of the web's five busiest sites and times how long |
128
|
|
each took. |
129
|
|
|
130
|
|
NAME TIME CUMULATIVE PERCENTAGE |
131
|
|
http://www.yahoo.com/ 3.892 3.892 22.399% |
132
|
|
http://www.google.com/ 3.259 7.152 18.758% |
133
|
|
http://www.msn.com/ 8.412 15.564 48.411% |
134
|
|
http://www.myspace.com/ 0.532 16.096 3.062% |
135
|
|
http://www.ebay.com/ 1.281 17.377 7.370% |
136
|
|
_stop_ 0.000 17.377 0.000% |
137
|
|
|
138
|
|
The final entry C<_stop_> is when the stop watch was stopped. |
139
|
|
|
140
|
|
=cut |
141
|
|
|
142
|
|
my $out = ''; |
143
|
|
my $header_format = "%-$self->{length}.$self->{length}s %-11s %-15s %s\n"; |
144
|
|
my $result_format = " %-$self->{length}.$self->{length}s %-11.3f %-15.3f %.3f%%\n"; |
145
|
|
my $prev_time = $self->{start}; |
146
|
|
push @{$self->{events}}, {name => '_stop_', time => $self->{stop}}; |
147
|
|
|
148
|
2
|
$out .= sprintf $header_format, qw( NAME TIME CUMULATIVE PERCENTAGE); |
|
2
|
|
|
2
|
|
149
|
2
|
|
150
|
2
|
foreach my $event (@{$self->{events}}) { |
151
|
2
|
|
152
|
2
|
my $duration = $event->{time} - $prev_time; |
153
|
2
|
my $cumulative = $event->{time} - $self->{start}; |
|
2
|
|
154
|
|
my $percentage = ($duration / $self->total_time) * 100; |
155
|
2
|
|
156
|
|
$out .= sprintf $result_format, # |
157
|
2
|
$event->{name}, # |
|
2
|
|
158
|
|
$duration, # |
159
|
71
|
$cumulative, # |
160
|
71
|
$percentage; |
161
|
71
|
|
162
|
|
$prev_time = $event->{time}; |
163
|
|
} |
164
|
|
|
165
|
71
|
pop @{$self->{events}}; |
166
|
|
return $out; |
167
|
|
} |
168
|
|
|
169
|
71
|
=head2 as_data |
170
|
|
|
171
|
|
my $data_structure_hashref = $stopwatch->as_data; |
172
|
2
|
|
|
2
|
|
173
|
2
|
Returns a data structure that contains all the information that was logged. |
174
|
|
This is so that you can use this module to gather the data but then use your |
175
|
|
own code to manipulate it. |
176
|
|
|
177
|
|
The returned hashref will look like this: |
178
|
|
|
179
|
|
{ |
180
|
|
start_time => 1234500, # The time the stopwatch was started |
181
|
|
stop_time => 1234510, # The time it was stopped or as_data called |
182
|
|
total_time => 10, # The duration of timing |
183
|
|
laps => [ |
184
|
|
{ |
185
|
|
name => 'test', # The name of the lap |
186
|
|
time => 1, # The time of this lap (seconds) |
187
|
|
cumulative => 1, # seconds since start to this lap |
188
|
|
fraction => 0.10, # fraction of total time. |
189
|
|
}, |
190
|
|
{ |
191
|
|
name => '_stop_', # created as needed |
192
|
|
time => 9, |
193
|
|
cumulative => 10, |
194
|
|
fraction => 0.9, |
195
|
|
}, |
196
|
|
], |
197
|
|
} |
198
|
|
|
199
|
|
=cut |
200
|
|
|
201
|
|
my %data = (); |
202
|
|
|
203
|
|
$data{start_time} = $self->{start}; |
204
|
|
$data{stop_time} = $self->{stop} || $self->time; |
205
|
|
$data{total_time} = $data{stop_time} - $data{start_time}; |
206
|
|
|
207
|
|
# Clone the events across and add the stop event. |
208
|
407
|
# $data{laps} = clone($self->{events}); |
|
407
|
|
|
407
|
|
209
|
407
|
my @laps = @{$self->{events}}; |
210
|
|
push @laps, {name => '_stop_', time => $data{stop_time}}; |
211
|
407
|
|
212
|
407
|
# For each entry in laps calculate the cumulative and the fraction. |
213
|
407
|
my $running_total = 0; |
214
|
|
my $last_time = $data{start_time}; |
215
|
|
foreach my $lap (@laps) { |
216
|
|
my %lapcopy = %$lap; |
217
|
407
|
my $this_time = delete $lapcopy{time}; |
|
407
|
|
218
|
407
|
$lapcopy{time} = $this_time - $last_time; |
219
|
|
$last_time = $this_time; |
220
|
|
|
221
|
407
|
$running_total += $lapcopy{time}; |
222
|
407
|
$lapcopy{cumulative} = $running_total; |
223
|
407
|
$lapcopy{fraction} = $lapcopy{time} / $data{total_time} if $data{total_time}; |
224
|
1373
|
|
225
|
1373
|
push @{$data{laps}}, \%lapcopy; |
226
|
1373
|
} |
227
|
1373
|
|
228
|
|
return \%data; |
229
|
1373
|
} |
230
|
1373
|
|
231
|
1373
|
|
232
|
|
=head1 AUTHOR |
233
|
1373
|
|
|
1373
|
|
234
|
|
Edmund von der Burg C<<evdb@ecclestoad.co.uk>> |
235
|
|
|
236
|
407
|
L<http://www.ecclestoad.co.uk> |
237
|
|
|
238
|
|
=head1 ACKNOWLEDGMENTS |
239
|
1849
|
|
|
1849
|
|
|
1849
|
|
|
1849
|
|
240
|
|
Inspiration from my colleagues at L<http://www.nestoria.co.uk> |
241
|
|
|
242
|
|
=head1 COPYRIGHT |
243
|
|
|
244
|
|
Copyright 2006 Edmund von der Burg |
245
|
|
|
246
|
|
SPDX-License-Identifier: Artistic-1.0 OR GPL-1.0-or-later |
247
|
|
=cut |
248
|
|
|
249
|
|
1; |