line |
stmt |
bran |
cond |
sub |
pod |
time |
code |
1
|
|
|
|
|
|
|
################################################## |
2
|
|
|
|
|
|
|
################################################## |
3
|
|
|
|
|
|
|
|
4
|
|
|
|
|
|
|
use 5.006; |
5
|
70
|
|
|
70
|
|
985
|
use strict; |
|
70
|
|
|
|
|
195
|
|
6
|
70
|
|
|
70
|
|
316
|
use warnings; |
|
70
|
|
|
|
|
155
|
|
|
70
|
|
|
|
|
1393
|
|
7
|
70
|
|
|
70
|
|
345
|
use Log::Log4perl::Util; |
|
70
|
|
|
|
|
177
|
|
|
70
|
|
|
|
|
1736
|
|
8
|
70
|
|
|
70
|
|
382
|
use Carp; |
|
70
|
|
|
|
|
154
|
|
|
70
|
|
|
|
|
2818
|
|
9
|
70
|
|
|
70
|
|
392
|
|
|
70
|
|
|
|
|
155
|
|
|
70
|
|
|
|
|
6994
|
|
10
|
|
|
|
|
|
|
our $TIME_HIRES_AVAILABLE; |
11
|
|
|
|
|
|
|
|
12
|
|
|
|
|
|
|
BEGIN { |
13
|
|
|
|
|
|
|
# Check if we've got Time::HiRes. If not, don't make a big fuss, |
14
|
|
|
|
|
|
|
# just set a flag so we know later on that we can't have fine-grained |
15
|
|
|
|
|
|
|
# time stamps |
16
|
|
|
|
|
|
|
$TIME_HIRES_AVAILABLE = 0; |
17
|
70
|
|
|
70
|
|
255
|
if(Log::Log4perl::Util::module_available("Time::HiRes")) { |
18
|
70
|
50
|
|
|
|
350
|
require Time::HiRes; |
19
|
70
|
|
|
|
|
337
|
$TIME_HIRES_AVAILABLE = 1; |
20
|
70
|
|
|
|
|
31779
|
} |
21
|
|
|
|
|
|
|
} |
22
|
|
|
|
|
|
|
|
23
|
|
|
|
|
|
|
################################################## |
24
|
|
|
|
|
|
|
################################################## |
25
|
|
|
|
|
|
|
my $class = shift; |
26
|
|
|
|
|
|
|
$class = ref ($class) || $class; |
27
|
215
|
|
|
215
|
0
|
427
|
|
28
|
215
|
|
33
|
|
|
781
|
my $self = { |
29
|
|
|
|
|
|
|
reset_time => undef, |
30
|
215
|
|
|
|
|
918
|
@_, |
31
|
|
|
|
|
|
|
}; |
32
|
|
|
|
|
|
|
|
33
|
|
|
|
|
|
|
$self->{time_function} = \&_gettimeofday unless |
34
|
|
|
|
|
|
|
defined $self->{time_function}; |
35
|
|
|
|
|
|
|
|
36
|
215
|
100
|
|
|
|
762
|
bless $self, $class; |
37
|
|
|
|
|
|
|
|
38
|
215
|
|
|
|
|
419
|
$self->reset(); |
39
|
|
|
|
|
|
|
|
40
|
215
|
|
|
|
|
625
|
return $self; |
41
|
|
|
|
|
|
|
} |
42
|
215
|
|
|
|
|
748
|
|
43
|
|
|
|
|
|
|
################################################## |
44
|
|
|
|
|
|
|
################################################## |
45
|
|
|
|
|
|
|
return $TIME_HIRES_AVAILABLE; |
46
|
|
|
|
|
|
|
} |
47
|
|
|
|
|
|
|
|
48
|
4
|
|
|
4
|
0
|
16
|
################################################## |
49
|
|
|
|
|
|
|
################################################## |
50
|
|
|
|
|
|
|
# Return secs and optionally msecs if we have Time::HiRes |
51
|
|
|
|
|
|
|
if($TIME_HIRES_AVAILABLE) { |
52
|
|
|
|
|
|
|
return (Time::HiRes::gettimeofday()); |
53
|
|
|
|
|
|
|
} else { |
54
|
|
|
|
|
|
|
return (time(), 0); |
55
|
363
|
50
|
|
363
|
|
816
|
} |
56
|
363
|
|
|
|
|
1558
|
} |
57
|
|
|
|
|
|
|
|
58
|
0
|
|
|
|
|
0
|
################################################## |
59
|
|
|
|
|
|
|
################################################## |
60
|
|
|
|
|
|
|
my($self) = @_; |
61
|
|
|
|
|
|
|
|
62
|
|
|
|
|
|
|
my($seconds, $microseconds) = $self->{time_function}->(); |
63
|
|
|
|
|
|
|
|
64
|
|
|
|
|
|
|
$microseconds = 0 if ! defined $microseconds; |
65
|
377
|
|
|
377
|
0
|
645
|
return($seconds, $microseconds); |
66
|
|
|
|
|
|
|
} |
67
|
377
|
|
|
|
|
1151
|
|
68
|
|
|
|
|
|
|
################################################## |
69
|
377
|
100
|
|
|
|
915
|
################################################## |
70
|
377
|
|
|
|
|
1026
|
my($self) = @_; |
71
|
|
|
|
|
|
|
|
72
|
|
|
|
|
|
|
my $current_time = [$self->gettimeofday()]; |
73
|
|
|
|
|
|
|
$self->{reset_time} = $current_time; |
74
|
|
|
|
|
|
|
$self->{last_call_time} = $current_time; |
75
|
|
|
|
|
|
|
|
76
|
215
|
|
|
215
|
0
|
467
|
return $current_time; |
77
|
|
|
|
|
|
|
} |
78
|
215
|
|
|
|
|
589
|
|
79
|
215
|
|
|
|
|
387
|
################################################## |
80
|
215
|
|
|
|
|
404
|
################################################## |
81
|
|
|
|
|
|
|
my($time_from, $time_to) = @_; |
82
|
215
|
|
|
|
|
395
|
|
83
|
|
|
|
|
|
|
my $seconds = $time_to->[0] - |
84
|
|
|
|
|
|
|
$time_from->[0]; |
85
|
|
|
|
|
|
|
|
86
|
|
|
|
|
|
|
my $milliseconds = int(( $time_to->[1] - |
87
|
|
|
|
|
|
|
$time_from->[1] ) / 1000); |
88
|
61
|
|
|
61
|
0
|
101
|
|
89
|
|
|
|
|
|
|
if($milliseconds < 0) { |
90
|
61
|
|
|
|
|
86
|
$milliseconds = 1000 + $milliseconds; |
91
|
|
|
|
|
|
|
$seconds--; |
92
|
|
|
|
|
|
|
} |
93
|
61
|
|
|
|
|
123
|
|
94
|
|
|
|
|
|
|
return($seconds, $milliseconds); |
95
|
|
|
|
|
|
|
} |
96
|
61
|
50
|
|
|
|
110
|
|
97
|
0
|
|
|
|
|
0
|
################################################## |
98
|
0
|
|
|
|
|
0
|
################################################## |
99
|
|
|
|
|
|
|
my($self, $current_time) = @_; |
100
|
|
|
|
|
|
|
|
101
|
61
|
|
|
|
|
96
|
$current_time = [ $self->gettimeofday() ] unless |
102
|
|
|
|
|
|
|
defined $current_time; |
103
|
|
|
|
|
|
|
|
104
|
|
|
|
|
|
|
my($seconds, $milliseconds) = time_diff( |
105
|
|
|
|
|
|
|
$self->{reset_time}, |
106
|
|
|
|
|
|
|
$current_time); |
107
|
53
|
|
|
53
|
0
|
83
|
|
108
|
|
|
|
|
|
|
return $seconds*1000 + $milliseconds; |
109
|
53
|
50
|
|
|
|
91
|
} |
110
|
|
|
|
|
|
|
|
111
|
|
|
|
|
|
|
################################################## |
112
|
|
|
|
|
|
|
################################################## |
113
|
|
|
|
|
|
|
my($self, $current_time) = @_; |
114
|
53
|
|
|
|
|
85
|
|
115
|
|
|
|
|
|
|
$current_time = [ $self->gettimeofday() ] unless |
116
|
53
|
|
|
|
|
139
|
defined $current_time; |
117
|
|
|
|
|
|
|
|
118
|
|
|
|
|
|
|
my($seconds, $milliseconds) = time_diff( |
119
|
|
|
|
|
|
|
$self->{last_call_time}, |
120
|
|
|
|
|
|
|
$current_time); |
121
|
|
|
|
|
|
|
|
122
|
8
|
|
|
8
|
0
|
14
|
$self->{last_call_time} = $current_time; |
123
|
|
|
|
|
|
|
|
124
|
8
|
50
|
|
|
|
13
|
return $seconds*1000 + $milliseconds; |
125
|
|
|
|
|
|
|
} |
126
|
|
|
|
|
|
|
|
127
|
|
|
|
|
|
|
1; |
128
|
|
|
|
|
|
|
|
129
|
8
|
|
|
|
|
14
|
|
130
|
|
|
|
|
|
|
=encoding utf8 |
131
|
8
|
|
|
|
|
15
|
|
132
|
|
|
|
|
|
|
=head1 NAME |
133
|
8
|
|
|
|
|
17
|
|
134
|
|
|
|
|
|
|
Log::Log4perl::Util::TimeTracker - Track time elapsed |
135
|
|
|
|
|
|
|
|
136
|
|
|
|
|
|
|
=head1 SYNOPSIS |
137
|
|
|
|
|
|
|
|
138
|
|
|
|
|
|
|
use Log::Log4perl::Util::TimeTracker; |
139
|
|
|
|
|
|
|
|
140
|
|
|
|
|
|
|
my $timer = Log::Log4perl::Util::TimeTracker->new(); |
141
|
|
|
|
|
|
|
|
142
|
|
|
|
|
|
|
# equivalent to Time::HiRes::gettimeofday(), regardless |
143
|
|
|
|
|
|
|
# if Time::HiRes is present or not. |
144
|
|
|
|
|
|
|
my($seconds, $microseconds) = $timer->gettimeofday(); |
145
|
|
|
|
|
|
|
|
146
|
|
|
|
|
|
|
# reset internal timer |
147
|
|
|
|
|
|
|
$timer->reset(); |
148
|
|
|
|
|
|
|
|
149
|
|
|
|
|
|
|
# return milliseconds since last reset |
150
|
|
|
|
|
|
|
$msecs = $timer->milliseconds(); |
151
|
|
|
|
|
|
|
|
152
|
|
|
|
|
|
|
# return milliseconds since last call |
153
|
|
|
|
|
|
|
$msecs = $timer->delta_milliseconds(); |
154
|
|
|
|
|
|
|
|
155
|
|
|
|
|
|
|
=head1 DESCRIPTION |
156
|
|
|
|
|
|
|
|
157
|
|
|
|
|
|
|
This utility module helps tracking time elapsed for PatternLayout's |
158
|
|
|
|
|
|
|
date and time placeholders. Its accuracy depends on the availability |
159
|
|
|
|
|
|
|
of the Time::HiRes module. If it's available, its granularity is |
160
|
|
|
|
|
|
|
milliseconds, if not, seconds. |
161
|
|
|
|
|
|
|
|
162
|
|
|
|
|
|
|
The most common use of this module is calling the gettimeofday() |
163
|
|
|
|
|
|
|
method: |
164
|
|
|
|
|
|
|
|
165
|
|
|
|
|
|
|
my($seconds, $microseconds) = $timer->gettimeofday(); |
166
|
|
|
|
|
|
|
|
167
|
|
|
|
|
|
|
It returns seconds and microseconds of the current epoch time. If |
168
|
|
|
|
|
|
|
Time::HiRes is installed, it will simply defer to its gettimeofday() |
169
|
|
|
|
|
|
|
function, if it's missing, time() will be called instead and $microseconds |
170
|
|
|
|
|
|
|
will always be 0. |
171
|
|
|
|
|
|
|
|
172
|
|
|
|
|
|
|
To measure time elapsed in milliseconds, use the reset() method to |
173
|
|
|
|
|
|
|
reset the timer to the current time, followed by one or more calls to |
174
|
|
|
|
|
|
|
the milliseconds() method: |
175
|
|
|
|
|
|
|
|
176
|
|
|
|
|
|
|
# reset internal timer |
177
|
|
|
|
|
|
|
$timer->reset(); |
178
|
|
|
|
|
|
|
|
179
|
|
|
|
|
|
|
# return milliseconds since last reset |
180
|
|
|
|
|
|
|
$msecs = $timer->milliseconds(); |
181
|
|
|
|
|
|
|
|
182
|
|
|
|
|
|
|
On top of the time span between the last reset and the current time, |
183
|
|
|
|
|
|
|
the module keeps track of the time between calls to delta_milliseconds(): |
184
|
|
|
|
|
|
|
|
185
|
|
|
|
|
|
|
$msecs = $timer->delta_milliseconds(); |
186
|
|
|
|
|
|
|
|
187
|
|
|
|
|
|
|
On the first call, this will return the number of milliseconds since the |
188
|
|
|
|
|
|
|
last reset(), on subsequent calls, it will return the time elapsed in |
189
|
|
|
|
|
|
|
milliseconds since the last call to delta_milliseconds() instead. Note |
190
|
|
|
|
|
|
|
that reset() also resets the time of the last call. |
191
|
|
|
|
|
|
|
|
192
|
|
|
|
|
|
|
The internal timer of this module gets its time input from the POSIX time() |
193
|
|
|
|
|
|
|
function, or, if the Time::HiRes module is available, from its |
194
|
|
|
|
|
|
|
gettimeofday() function. To figure out which one it is, use |
195
|
|
|
|
|
|
|
|
196
|
|
|
|
|
|
|
if( $timer->hires_available() ) { |
197
|
|
|
|
|
|
|
print "Hooray, we get real milliseconds!\n"; |
198
|
|
|
|
|
|
|
} else { |
199
|
|
|
|
|
|
|
print "Milliseconds are just bogus\n"; |
200
|
|
|
|
|
|
|
} |
201
|
|
|
|
|
|
|
|
202
|
|
|
|
|
|
|
For testing purposes, a different time source can be provided, so test |
203
|
|
|
|
|
|
|
suites can simulate time passing by without actually having to wait: |
204
|
|
|
|
|
|
|
|
205
|
|
|
|
|
|
|
my $start_time = time(); |
206
|
|
|
|
|
|
|
|
207
|
|
|
|
|
|
|
my $timer = Log::Log4perl::Util::TimeTracker->new( |
208
|
|
|
|
|
|
|
time_function => sub { |
209
|
|
|
|
|
|
|
return $start_time++; |
210
|
|
|
|
|
|
|
}, |
211
|
|
|
|
|
|
|
); |
212
|
|
|
|
|
|
|
|
213
|
|
|
|
|
|
|
Every call to $timer->epoch() will then return a time value that is one |
214
|
|
|
|
|
|
|
second ahead of the value returned on the previous call. This also means |
215
|
|
|
|
|
|
|
that every call to delta_milliseconds() will return a value that exceeds |
216
|
|
|
|
|
|
|
the value returned on the previous call by 1000. |
217
|
|
|
|
|
|
|
|
218
|
|
|
|
|
|
|
=head1 LICENSE |
219
|
|
|
|
|
|
|
|
220
|
|
|
|
|
|
|
Copyright 2002-2013 by Mike Schilli E<lt>m@perlmeister.comE<gt> |
221
|
|
|
|
|
|
|
and Kevin Goess E<lt>cpan@goess.orgE<gt>. |
222
|
|
|
|
|
|
|
|
223
|
|
|
|
|
|
|
This library is free software; you can redistribute it and/or modify |
224
|
|
|
|
|
|
|
it under the same terms as Perl itself. |
225
|
|
|
|
|
|
|
|
226
|
|
|
|
|
|
|
=head1 AUTHOR |
227
|
|
|
|
|
|
|
|
228
|
|
|
|
|
|
|
Please contribute patches to the project on Github: |
229
|
|
|
|
|
|
|
|
230
|
|
|
|
|
|
|
http://github.com/mschilli/log4perl |
231
|
|
|
|
|
|
|
|
232
|
|
|
|
|
|
|
Send bug reports or requests for enhancements to the authors via our |
233
|
|
|
|
|
|
|
|
234
|
|
|
|
|
|
|
MAILING LIST (questions, bug reports, suggestions/patches): |
235
|
|
|
|
|
|
|
log4perl-devel@lists.sourceforge.net |
236
|
|
|
|
|
|
|
|
237
|
|
|
|
|
|
|
Authors (please contact them via the list above, not directly): |
238
|
|
|
|
|
|
|
Mike Schilli <m@perlmeister.com>, |
239
|
|
|
|
|
|
|
Kevin Goess <cpan@goess.org> |
240
|
|
|
|
|
|
|
|
241
|
|
|
|
|
|
|
Contributors (in alphabetical order): |
242
|
|
|
|
|
|
|
Ateeq Altaf, Cory Bennett, Jens Berthold, Jeremy Bopp, Hutton |
243
|
|
|
|
|
|
|
Davidson, Chris R. Donnelly, Matisse Enzer, Hugh Esco, Anthony |
244
|
|
|
|
|
|
|
Foiani, James FitzGibbon, Carl Franks, Dennis Gregorovic, Andy |
245
|
|
|
|
|
|
|
Grundman, Paul Harrington, Alexander Hartmaier David Hull, |
246
|
|
|
|
|
|
|
Robert Jacobson, Jason Kohles, Jeff Macdonald, Markus Peter, |
247
|
|
|
|
|
|
|
Brett Rann, Peter Rabbitson, Erik Selberg, Aaron Straup Cope, |
248
|
|
|
|
|
|
|
Lars Thegler, David Viner, Mac Yang. |
249
|
|
|
|
|
|
|
|