File Coverage

OpenQA/Benchmark/Stopwatch.pm
Criterion Covered Total %
statement 86 86 100.0
total 86 86 100.0


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;