line |
stmt |
bran |
cond |
sub |
pod |
time |
code |
1
|
|
|
|
|
|
|
package DashProfiler::Core; |
2
|
|
|
|
|
|
|
|
3
|
|
|
|
|
|
|
=head1 NAME |
4
|
|
|
|
|
|
|
|
5
|
|
|
|
|
|
|
DashProfiler::Core - DashProfiler core object and sampler factory |
6
|
|
|
|
|
|
|
|
7
|
|
|
|
|
|
|
=head1 SYNOPSIS |
8
|
|
|
|
|
|
|
|
9
|
|
|
|
|
|
|
See L for a general introduction. |
10
|
|
|
|
|
|
|
|
11
|
|
|
|
|
|
|
DashProfiler::Core is currently viewed as an internal class. The interface may change. |
12
|
|
|
|
|
|
|
The DashProfiler and DashProfiler::Import modules are the usual interfaces. |
13
|
|
|
|
|
|
|
|
14
|
|
|
|
|
|
|
=head1 DESCRIPTION |
15
|
|
|
|
|
|
|
|
16
|
|
|
|
|
|
|
A DashProfiler::Core objects are the core of the DashProfiler, naturally. |
17
|
|
|
|
|
|
|
They sit between the 'samplers' that feed data into a core, and the DBI::Profile |
18
|
|
|
|
|
|
|
objects that aggregate those samples. A core may have multiple samplers and |
19
|
|
|
|
|
|
|
multiple profiles. |
20
|
|
|
|
|
|
|
|
21
|
|
|
|
|
|
|
=cut |
22
|
|
|
|
|
|
|
|
23
|
5
|
|
|
5
|
|
155399
|
use strict; |
|
5
|
|
|
|
|
13
|
|
|
5
|
|
|
|
|
337
|
|
24
|
|
|
|
|
|
|
|
25
|
|
|
|
|
|
|
our $VERSION = sprintf("1.%06d", q$Revision: 48 $ =~ /(\d+)/o); |
26
|
|
|
|
|
|
|
|
27
|
5
|
|
|
5
|
|
9613
|
use DBI 1.57 qw(dbi_time dbi_profile_merge); |
|
5
|
|
|
|
|
71347
|
|
|
5
|
|
|
|
|
810
|
|
28
|
5
|
|
|
5
|
|
5662
|
use DBI::Profile; |
|
5
|
|
|
|
|
17247
|
|
|
5
|
|
|
|
|
423
|
|
29
|
5
|
|
|
5
|
|
4485
|
use DBI::ProfileDumper; |
|
5
|
|
|
|
|
13089
|
|
|
5
|
|
|
|
|
230
|
|
30
|
5
|
|
|
5
|
|
37
|
use Carp; |
|
5
|
|
|
|
|
11
|
|
|
5
|
|
|
|
|
463
|
|
31
|
|
|
|
|
|
|
|
32
|
|
|
|
|
|
|
our $ENDING = 0; |
33
|
|
|
|
|
|
|
|
34
|
|
|
|
|
|
|
BEGIN { |
35
|
|
|
|
|
|
|
# use env var to control debugging at compile-time |
36
|
5
|
|
50
|
5
|
|
74
|
my $debug = $ENV{DASHPROFILER_CORE_DEBUG} || $ENV{DASHPROFILER_DEBUG} || 0; |
37
|
5
|
50
|
|
|
|
346
|
eval "sub DEBUG () { $debug }; 1;" or die; ## no critic |
38
|
|
|
|
|
|
|
} |
39
|
|
|
|
|
|
|
END { |
40
|
5
|
|
|
5
|
|
2190
|
$ENDING = 1; |
41
|
|
|
|
|
|
|
} |
42
|
|
|
|
|
|
|
|
43
|
|
|
|
|
|
|
|
44
|
|
|
|
|
|
|
BEGIN { |
45
|
|
|
|
|
|
|
# load Hash::Util for lock_keys() |
46
|
|
|
|
|
|
|
# if Hash::Util isn't available then install a stub for lock_keys() |
47
|
5
|
|
|
5
|
|
13
|
eval { |
48
|
5
|
|
|
|
|
4641
|
require Hash::Util; |
49
|
5
|
|
|
|
|
12394
|
Hash::Util->import('lock_keys'); |
50
|
|
|
|
|
|
|
}; |
51
|
5
|
50
|
33
|
|
|
327
|
die @$ if $@ && $@ !~ /^Can't locate Hash\/Util/; |
52
|
5
|
50
|
|
|
|
13105
|
*lock_keys = sub { } if not defined &lock_keys; |
|
0
|
|
|
|
|
0
|
|
53
|
|
|
|
|
|
|
} |
54
|
|
|
|
|
|
|
|
55
|
|
|
|
|
|
|
|
56
|
|
|
|
|
|
|
# check for weaken support, used by ChildHandles |
57
|
|
|
|
|
|
|
my $HAS_WEAKEN = eval { |
58
|
|
|
|
|
|
|
require Scalar::Util; |
59
|
|
|
|
|
|
|
# this will croak() if this Scalar::Util doesn't have a working weaken(). |
60
|
|
|
|
|
|
|
Scalar::Util::weaken( my $test = [] ); |
61
|
|
|
|
|
|
|
1; |
62
|
|
|
|
|
|
|
}; |
63
|
|
|
|
|
|
|
*weaken = sub { croak "Can't weaken without Scalar::Util::weaken" } |
64
|
|
|
|
|
|
|
unless $HAS_WEAKEN; |
65
|
|
|
|
|
|
|
|
66
|
|
|
|
|
|
|
|
67
|
|
|
|
|
|
|
# On 2GHz OS X 10.5.2 laptop: |
68
|
|
|
|
|
|
|
# sample_overhead_time = 0.000014s |
69
|
|
|
|
|
|
|
# sample_inner_time = 0.000003s |
70
|
|
|
|
|
|
|
my ($sample_overhead_time, $sample_inner_time) = estimate_sample_overheads(); |
71
|
|
|
|
|
|
|
|
72
|
|
|
|
|
|
|
|
73
|
|
|
|
|
|
|
=head1 CLASS METHODS |
74
|
|
|
|
|
|
|
|
75
|
|
|
|
|
|
|
=head2 new |
76
|
|
|
|
|
|
|
|
77
|
|
|
|
|
|
|
$obj = DashProfiler::Core->new( 'foo' ); |
78
|
|
|
|
|
|
|
|
79
|
|
|
|
|
|
|
$obj = DashProfiler::Core->new( 'bar', { ...options... } ); |
80
|
|
|
|
|
|
|
|
81
|
|
|
|
|
|
|
$obj = DashProfiler::Core->new( extsys => { |
82
|
|
|
|
|
|
|
granularity => 10, |
83
|
|
|
|
|
|
|
flush_interval => 300, |
84
|
|
|
|
|
|
|
} ); |
85
|
|
|
|
|
|
|
|
86
|
|
|
|
|
|
|
Creates and returns a DashProfiler::Core object. |
87
|
|
|
|
|
|
|
|
88
|
|
|
|
|
|
|
=head2 Options for new() |
89
|
|
|
|
|
|
|
|
90
|
|
|
|
|
|
|
=head3 disabled |
91
|
|
|
|
|
|
|
|
92
|
|
|
|
|
|
|
Set to a true value to prevent samples being added to this core. If true, the |
93
|
|
|
|
|
|
|
prepare() method and the L new() method will return undef. |
94
|
|
|
|
|
|
|
|
95
|
|
|
|
|
|
|
Default false. |
96
|
|
|
|
|
|
|
|
97
|
|
|
|
|
|
|
Currently, any existing samples that were active will still be added when they |
98
|
|
|
|
|
|
|
terminate. This behaviour may change. |
99
|
|
|
|
|
|
|
|
100
|
|
|
|
|
|
|
See also L. |
101
|
|
|
|
|
|
|
|
102
|
|
|
|
|
|
|
=head3 dbi_profile_class |
103
|
|
|
|
|
|
|
|
104
|
|
|
|
|
|
|
Specifies the class to use for creating DBI::Profile objects. |
105
|
|
|
|
|
|
|
The default is C. Alternatives include C |
106
|
|
|
|
|
|
|
and C. |
107
|
|
|
|
|
|
|
|
108
|
|
|
|
|
|
|
=head3 dbi_profile_args |
109
|
|
|
|
|
|
|
|
110
|
|
|
|
|
|
|
Specifies extra arguments to pass the new() method of the C |
111
|
|
|
|
|
|
|
(e.g., C). The default is C<{ }>. |
112
|
|
|
|
|
|
|
|
113
|
|
|
|
|
|
|
=head3 flush_interval |
114
|
|
|
|
|
|
|
|
115
|
|
|
|
|
|
|
How frequently the DBI:Profiles associated with this core should be written out |
116
|
|
|
|
|
|
|
and the data reset. Default is 0 - no regular flushing. |
117
|
|
|
|
|
|
|
|
118
|
|
|
|
|
|
|
=head3 flush_hook |
119
|
|
|
|
|
|
|
|
120
|
|
|
|
|
|
|
If set, this code reference is called when flush() is called and can influence |
121
|
|
|
|
|
|
|
its behaviour. For example, this is the flush_hook used by L: |
122
|
|
|
|
|
|
|
|
123
|
|
|
|
|
|
|
flush_hook => sub { |
124
|
|
|
|
|
|
|
my ($self, $dbi_profile_name) = @_; |
125
|
|
|
|
|
|
|
warn $_ for $self->profile_as_text($dbi_profile_name); |
126
|
|
|
|
|
|
|
return $self->reset_profile_data($dbi_profile_name); |
127
|
|
|
|
|
|
|
}, |
128
|
|
|
|
|
|
|
|
129
|
|
|
|
|
|
|
See L for more details. |
130
|
|
|
|
|
|
|
|
131
|
|
|
|
|
|
|
=head3 granularity |
132
|
|
|
|
|
|
|
|
133
|
|
|
|
|
|
|
The default C for the DBI::Profile objects doesn't include time. |
134
|
|
|
|
|
|
|
The granularity option adds 'C' to the front of the Path. |
135
|
|
|
|
|
|
|
So as time passes the samples are aggregated into new sub-trees. |
136
|
|
|
|
|
|
|
|
137
|
|
|
|
|
|
|
=head3 sample_class |
138
|
|
|
|
|
|
|
|
139
|
|
|
|
|
|
|
The sample_class option specifies which class should be used to take profile samples. |
140
|
|
|
|
|
|
|
The default is C. |
141
|
|
|
|
|
|
|
See the L method for more information. |
142
|
|
|
|
|
|
|
|
143
|
|
|
|
|
|
|
=head3 period_summary |
144
|
|
|
|
|
|
|
|
145
|
|
|
|
|
|
|
Specifies the name of an extra DBI Profile object to attach to the core. |
146
|
|
|
|
|
|
|
This extra 'period summary' profile is enabled and reset by the start_sample_period() |
147
|
|
|
|
|
|
|
method and disabled by the end_sample_period() method. |
148
|
|
|
|
|
|
|
|
149
|
|
|
|
|
|
|
The mechanism enables a single profile to be used to capture both long-running |
150
|
|
|
|
|
|
|
sampling (often with C set) and single-period (e.g., for a 'debug' |
151
|
|
|
|
|
|
|
footer on a generated web page) |
152
|
|
|
|
|
|
|
|
153
|
|
|
|
|
|
|
=head3 period_exclusive |
154
|
|
|
|
|
|
|
|
155
|
|
|
|
|
|
|
When using periods, via the start_sample_period() and end_sample_period() methods, |
156
|
|
|
|
|
|
|
DashProfiler can add an additional sample representing the time between the |
157
|
|
|
|
|
|
|
start_sample_period() and end_sample_period() method calls that I |
158
|
|
|
|
|
|
|
accounted for by the samples. |
159
|
|
|
|
|
|
|
|
160
|
|
|
|
|
|
|
The period_exclusive option enables this extra sample. The value of the option |
161
|
|
|
|
|
|
|
is used as the value for key1 and key2 in the Path. |
162
|
|
|
|
|
|
|
|
163
|
|
|
|
|
|
|
=head3 period_strict_start |
164
|
|
|
|
|
|
|
|
165
|
|
|
|
|
|
|
See L. |
166
|
|
|
|
|
|
|
|
167
|
|
|
|
|
|
|
=head3 period_strict_end |
168
|
|
|
|
|
|
|
|
169
|
|
|
|
|
|
|
See L. |
170
|
|
|
|
|
|
|
|
171
|
|
|
|
|
|
|
=head3 profile_as_text_args |
172
|
|
|
|
|
|
|
|
173
|
|
|
|
|
|
|
A reference to a hash containing default formatting arguments for the profile_as_text() method. |
174
|
|
|
|
|
|
|
|
175
|
|
|
|
|
|
|
=head3 extra_info |
176
|
|
|
|
|
|
|
|
177
|
|
|
|
|
|
|
Can be used to attach any extra information to the profiler core object. That can be useful sometimes in callbacks. |
178
|
|
|
|
|
|
|
|
179
|
|
|
|
|
|
|
=cut |
180
|
|
|
|
|
|
|
|
181
|
|
|
|
|
|
|
sub new { |
182
|
12
|
|
|
12
|
1
|
706
|
my ($class, $profile_name, $opt_params) = @_; |
183
|
12
|
|
50
|
|
|
39
|
$opt_params ||= {}; |
184
|
12
|
50
|
33
|
|
|
87
|
croak "No profile_name given" unless $profile_name && not ref $profile_name; |
185
|
12
|
50
|
|
|
|
46
|
croak "$class->new($profile_name, $opt_params) options must be a hash reference" |
186
|
|
|
|
|
|
|
if ref $opt_params ne 'HASH'; |
187
|
|
|
|
|
|
|
|
188
|
12
|
|
100
|
|
|
89
|
our $opt_defaults ||= { |
189
|
|
|
|
|
|
|
disabled => 0, |
190
|
|
|
|
|
|
|
sample_class => 'DashProfiler::Sample', |
191
|
|
|
|
|
|
|
dbi_profile_class => 'DBI::Profile', |
192
|
|
|
|
|
|
|
dbi_profile_args => {}, |
193
|
|
|
|
|
|
|
flush_interval => 0, |
194
|
|
|
|
|
|
|
flush_hook => undef, |
195
|
|
|
|
|
|
|
granularity => 0, |
196
|
|
|
|
|
|
|
period_exclusive => undef, |
197
|
|
|
|
|
|
|
period_summary => undef, |
198
|
|
|
|
|
|
|
period_strict_start => 0x01, |
199
|
|
|
|
|
|
|
period_strict_end => 0x00, |
200
|
|
|
|
|
|
|
profile_as_text_args => undef, |
201
|
|
|
|
|
|
|
extra_info => undef, # for caller to hook in their own data |
202
|
|
|
|
|
|
|
}; |
203
|
0
|
|
|
|
|
0
|
croak "Invalid options: ".join(', ', grep { !$opt_defaults->{$_} } keys %$opt_params) |
|
12
|
|
|
|
|
176
|
|
204
|
12
|
50
|
|
|
|
17
|
if keys %{ { %$opt_defaults, %$opt_params } } > keys %$opt_defaults; |
205
|
|
|
|
|
|
|
|
206
|
12
|
|
|
|
|
106
|
my $time = dbi_time(); |
207
|
12
|
|
|
|
|
193
|
my $self = bless { |
208
|
|
|
|
|
|
|
profile_name => $profile_name, |
209
|
|
|
|
|
|
|
in_use => 0, |
210
|
|
|
|
|
|
|
in_use_warning_given => 0, |
211
|
|
|
|
|
|
|
dbi_handles_all => {}, |
212
|
|
|
|
|
|
|
dbi_handles_active => {}, |
213
|
|
|
|
|
|
|
flush_due_at_time => undef, |
214
|
|
|
|
|
|
|
# for start_period |
215
|
|
|
|
|
|
|
period_count => 0, |
216
|
|
|
|
|
|
|
period_start_time => 0, |
217
|
|
|
|
|
|
|
period_accumulated => 0, |
218
|
|
|
|
|
|
|
exclusive_sampler => undef, |
219
|
|
|
|
|
|
|
%$opt_defaults, |
220
|
|
|
|
|
|
|
%$opt_params, |
221
|
|
|
|
|
|
|
} => $class; |
222
|
12
|
|
|
|
|
91
|
$self->{flush_due_at_time} = $time + $self->{flush_interval}; |
223
|
|
|
|
|
|
|
|
224
|
12
|
|
|
|
|
119
|
lock_keys(%$self); |
225
|
|
|
|
|
|
|
|
226
|
12
|
|
|
|
|
178
|
_load_class($self->{sample_class}); |
227
|
|
|
|
|
|
|
|
228
|
12
|
100
|
|
|
|
49
|
if (my $exclusive_name = $self->{period_exclusive}) { |
229
|
|
|
|
|
|
|
# create the sampler through which period_exclusive samples are added |
230
|
|
|
|
|
|
|
# by end_sample_period() |
231
|
2
|
|
|
|
|
10
|
$self->{exclusive_sampler} = $self->prepare($exclusive_name, $exclusive_name); |
232
|
|
|
|
|
|
|
} |
233
|
12
|
|
|
|
|
56
|
my $dbi_profile = $self->_mk_dbi_profile($self->{dbi_profile_class}, $self->{granularity}); |
234
|
12
|
|
|
|
|
47
|
$self->attach_dbi_profile( $dbi_profile, "main", 0 ); |
235
|
|
|
|
|
|
|
|
236
|
12
|
100
|
|
|
|
51
|
if (my $period_summary = $self->{period_summary}) { |
237
|
1
|
|
|
|
|
4
|
my $dbi_profile = $self->_mk_dbi_profile("DashProfiler::DumpNowhere", 0); |
238
|
1
|
|
|
|
|
3
|
my $dbh = $self->attach_dbi_profile( $dbi_profile, "period_summary", 0 ); |
239
|
1
|
|
|
|
|
5
|
$self->{dbi_handles_all}{period_summary} = $dbh; |
240
|
|
|
|
|
|
|
# start_sample_period() will add handle to {dbi_handles_active} |
241
|
|
|
|
|
|
|
} |
242
|
|
|
|
|
|
|
|
243
|
|
|
|
|
|
|
# mark as in_use if disabled as this allows the sampler to be more efficient |
244
|
12
|
50
|
|
|
|
37
|
$self->{in_use} = -42 if $self->{disabled}; |
245
|
|
|
|
|
|
|
|
246
|
12
|
|
|
|
|
34
|
return $self; |
247
|
|
|
|
|
|
|
} |
248
|
|
|
|
|
|
|
|
249
|
|
|
|
|
|
|
|
250
|
|
|
|
|
|
|
=head2 estimate_sample_overheads |
251
|
|
|
|
|
|
|
|
252
|
|
|
|
|
|
|
$sample_overhead_time = DashProfiler::Core->estimate_sample_overheads(); |
253
|
|
|
|
|
|
|
|
254
|
|
|
|
|
|
|
($sample_overhead_time, $sample_inner_time) |
255
|
|
|
|
|
|
|
= DashProfiler::Core->estimate_sample_overheads(); |
256
|
|
|
|
|
|
|
|
257
|
|
|
|
|
|
|
Estimates and returns the approximate minimum time overhead for taking a sample. |
258
|
|
|
|
|
|
|
Two times are returned. The following timeline diagram explains the difference: |
259
|
|
|
|
|
|
|
|
260
|
|
|
|
|
|
|
previous statement ------------- |
261
|
|
|
|
|
|
|
| |
262
|
|
|
|
|
|
|
sampler called | |
263
|
|
|
|
|
|
|
sampler does work | |
264
|
|
|
|
|
|
|
sampler reads time ----- | |
265
|
|
|
|
|
|
|
sampler does work | | |
266
|
|
|
|
|
|
|
return sample object | | |
267
|
|
|
|
|
|
|
| | |
268
|
|
|
|
|
|
|
(measured statements) | | |
269
|
|
|
|
|
|
|
| | |
270
|
|
|
|
|
|
|
sample DESTROY'd | | |
271
|
|
|
|
|
|
|
sample does work v | |
272
|
|
|
|
|
|
|
sample reads time ----- | = sample_inner_time |
273
|
|
|
|
|
|
|
sample does work | |
274
|
|
|
|
|
|
|
v |
275
|
|
|
|
|
|
|
next statement ------------- = sample_overhead_time |
276
|
|
|
|
|
|
|
|
277
|
|
|
|
|
|
|
For estimate_sample_overheads() there are no I so the |
278
|
|
|
|
|
|
|
times reflect the pure overheads. |
279
|
|
|
|
|
|
|
|
280
|
|
|
|
|
|
|
Note that because estimate_sample_overheads() uses a tight loop, the timings |
281
|
|
|
|
|
|
|
returned are likely to be I smaller then the timings you'd get in |
282
|
|
|
|
|
|
|
practice due to CPU L2 caches and other factors. This is okay. |
283
|
|
|
|
|
|
|
On my 2GHz laptop running OS X 10.5.2 $sample_overhead_time is 0.000014 and |
284
|
|
|
|
|
|
|
$sample_inner_time is 0.000003. (When doing occasional sampling the |
285
|
|
|
|
|
|
|
sample_overhead_time is 0.000002 to 0.000003 higher, in case you care.) |
286
|
|
|
|
|
|
|
|
287
|
|
|
|
|
|
|
DashProfiler automatically calls estimate_sample_overheads() when loading and |
288
|
|
|
|
|
|
|
records the returned values. It then uses the C to |
289
|
|
|
|
|
|
|
adjust the L time to more accrately reflect the time not |
290
|
|
|
|
|
|
|
covered by the accumulated samples. Currently the C is |
291
|
|
|
|
|
|
|
I subtracted from the individual samples. That may change in future. |
292
|
|
|
|
|
|
|
|
293
|
|
|
|
|
|
|
=cut |
294
|
|
|
|
|
|
|
|
295
|
|
|
|
|
|
|
sub estimate_sample_overheads { |
296
|
6
|
|
|
6
|
1
|
24
|
my ($self, $count) = @_; |
297
|
6
|
|
50
|
|
|
44
|
$count ||= 1000; |
298
|
|
|
|
|
|
|
|
299
|
6
|
|
|
|
|
35
|
my $profile = __PACKAGE__->new('overhead',{ dbi_profile_class => 'DashProfiler::DumpNowhere' }); |
300
|
6
|
|
|
|
|
33
|
my $sampler = $profile->prepare('c1'); |
301
|
|
|
|
|
|
|
# It's okay that this is a tight loop so will tend to give lower times |
302
|
|
|
|
|
|
|
# than would be experienced in practice because, while we want to get as |
303
|
|
|
|
|
|
|
# close as possible to the true overhead, we don't want to overestimate it. |
304
|
6
|
|
|
|
|
15
|
my ($i, $sum) = ($count, 0); |
305
|
6
|
|
|
|
|
21
|
while ($i--) { |
306
|
6000
|
|
|
|
|
10360
|
my $t0 = dbi_time(); # to compare with t1 below |
307
|
6000
|
|
|
|
|
9502
|
my $t1 = dbi_time(); # time before sampling |
308
|
6000
|
|
|
|
|
8924
|
my $ps1 = $sampler->("c2"); # begin sample |
309
|
6000
|
|
|
|
|
7374
|
undef $ps1; # end sample |
310
|
6000
|
|
|
|
|
13481
|
$sum += (dbi_time() - $t1) # time to perform full sample lifecycle |
311
|
|
|
|
|
|
|
- ($t1 - $t0); # subtract cost of calling dbi_time() |
312
|
|
|
|
|
|
|
} |
313
|
|
|
|
|
|
|
# overhead is average of time spent calling sampler & DESTROY: |
314
|
6
|
|
|
|
|
33
|
$sample_overhead_time = $sum / $count; # ~0.000014s on 2GHz OS X 10.5.2 laptop |
315
|
6
|
|
|
|
|
36
|
$sample_inner_time = ($profile->get_dbi_profile->{Data}{c1}{c2}[1] / $count); |
316
|
|
|
|
|
|
|
|
317
|
|
|
|
|
|
|
# we could also subtract the time accumulated by the samples, like this: |
318
|
|
|
|
|
|
|
# $sample_overhead_time -= $sample_inner_time |
319
|
|
|
|
|
|
|
# but we don't because that's also a valid part of the overhead |
320
|
|
|
|
|
|
|
# because there are no statements between the sample creation and destruction. |
321
|
|
|
|
|
|
|
|
322
|
6
|
|
|
|
|
11
|
warn sprintf "sample_overhead_time=%.7fs (sample_inner_time=%.7fs)\n", |
323
|
|
|
|
|
|
|
$sample_overhead_time, $sample_inner_time if DEBUG(); |
324
|
|
|
|
|
|
|
|
325
|
6
|
|
|
|
|
30
|
$profile->reset_profile_data; |
326
|
|
|
|
|
|
|
|
327
|
6
|
50
|
|
|
|
37
|
return $sample_overhead_time unless wantarray; |
328
|
6
|
|
|
|
|
69
|
return ($sample_overhead_time, $sample_inner_time); |
329
|
|
|
|
|
|
|
} |
330
|
|
|
|
|
|
|
|
331
|
|
|
|
|
|
|
|
332
|
|
|
|
|
|
|
|
333
|
|
|
|
|
|
|
=head1 OBJECT METHODS |
334
|
|
|
|
|
|
|
|
335
|
|
|
|
|
|
|
=head2 attach_dbi_profile |
336
|
|
|
|
|
|
|
|
337
|
|
|
|
|
|
|
$core->attach_dbi_profile( $dbi_profile, $name ); |
338
|
|
|
|
|
|
|
|
339
|
|
|
|
|
|
|
Attaches a DBI Profile to a DashProfiler::Core object using the $name given. |
340
|
|
|
|
|
|
|
Any later samples are also aggregated into this DBI Profile. |
341
|
|
|
|
|
|
|
|
342
|
|
|
|
|
|
|
Not normally called directly. The new() method calls attach_dbi_profile() to |
343
|
|
|
|
|
|
|
attach the "main" profile and the C profile, if enabled. |
344
|
|
|
|
|
|
|
|
345
|
|
|
|
|
|
|
The $dbi_profile argument can be either a DBI::Profile object or a string |
346
|
|
|
|
|
|
|
containing a DBI::Profile specification. |
347
|
|
|
|
|
|
|
|
348
|
|
|
|
|
|
|
The get_dbi_profile($name) method can be used to retrieve the profile. |
349
|
|
|
|
|
|
|
|
350
|
|
|
|
|
|
|
=cut |
351
|
|
|
|
|
|
|
|
352
|
|
|
|
|
|
|
sub attach_dbi_profile { |
353
|
13
|
|
|
13
|
1
|
29
|
my ($self, $dbi_profile, $dbi_profile_name, $weakly) = @_; |
354
|
|
|
|
|
|
|
# wrap DBI::Profile object/spec with a DBI handle |
355
|
13
|
50
|
|
|
|
41
|
croak "No dbi_profile_name specified" unless defined $dbi_profile_name; |
356
|
13
|
|
|
|
|
56
|
local $ENV{DBI_AUTOPROXY}; |
357
|
13
|
|
|
|
|
124
|
my $dbh = DBI->connect("dbi:DashProfiler:", "", "", { |
358
|
|
|
|
|
|
|
Profile => $dbi_profile, |
359
|
|
|
|
|
|
|
RaiseError => 1, PrintError => 1, TraceLevel => 0, |
360
|
|
|
|
|
|
|
}); |
361
|
13
|
|
|
|
|
80
|
$dbh = tied %$dbh; # switch to inner handle |
362
|
13
|
|
|
|
|
142
|
$dbh->{Profile}->empty; # discard FETCH&STOREs etc due to connect() |
363
|
13
|
|
|
|
|
94
|
for my $handles ($self->{dbi_handles_all}, $self->{dbi_handles_active}) { |
364
|
|
|
|
|
|
|
# clean out any dead weakrefs |
365
|
26
|
|
33
|
|
|
78
|
defined $handles->{$_} or delete $handles->{$_} for keys %$handles; |
366
|
26
|
|
|
|
|
62
|
$handles->{$dbi_profile_name} = $dbh; |
367
|
|
|
|
|
|
|
# weaken($handles->{$dbi_profile_name}) if $weakly; # not currently documented or used |
368
|
|
|
|
|
|
|
} |
369
|
13
|
|
|
|
|
99
|
return $dbh; |
370
|
|
|
|
|
|
|
} |
371
|
|
|
|
|
|
|
|
372
|
|
|
|
|
|
|
|
373
|
|
|
|
|
|
|
sub _attach_new_temporary_plain_profile { # not currently documented or used |
374
|
0
|
|
|
0
|
|
0
|
my ($self, $dbi_profile_name) = @_; |
375
|
|
|
|
|
|
|
# create new DBI profile (with no time key) that doesn't flush anywhere |
376
|
0
|
|
|
|
|
0
|
my $dbi_profile = $self->_mk_dbi_profile("DashProfiler::DumpNowhere", 0); |
377
|
|
|
|
|
|
|
# attach to the profile, but only weakly |
378
|
0
|
|
|
|
|
0
|
$self->attach_dbi_profile( $dbi_profile, $dbi_profile_name, 1 ); |
379
|
|
|
|
|
|
|
# return ref so caller can store till ready to discard |
380
|
0
|
|
|
|
|
0
|
return $dbi_profile; |
381
|
|
|
|
|
|
|
} |
382
|
|
|
|
|
|
|
|
383
|
|
|
|
|
|
|
|
384
|
|
|
|
|
|
|
sub _mk_dbi_profile { |
385
|
13
|
|
|
13
|
|
29
|
my ($self, $class, $granularity) = @_; |
386
|
|
|
|
|
|
|
|
387
|
13
|
|
|
|
|
38
|
_load_class($class); |
388
|
13
|
100
|
|
|
|
71
|
my $Path = $granularity ? [ "!Time~$granularity", "!Statement", "!MethodName" ] |
389
|
|
|
|
|
|
|
: [ "!Statement", "!MethodName" ]; |
390
|
13
|
|
|
|
|
150
|
my $dbi_profile = $class->new( |
391
|
|
|
|
|
|
|
Path => $Path, |
392
|
|
|
|
|
|
|
Quiet => 1, |
393
|
|
|
|
|
|
|
Trace => 0, |
394
|
|
|
|
|
|
|
File => "dashprofile.$self->{profile_name}", |
395
|
13
|
|
|
|
|
42
|
%{ $self->{dbi_profile_args} }, |
396
|
|
|
|
|
|
|
); |
397
|
|
|
|
|
|
|
|
398
|
13
|
|
|
|
|
445
|
return $dbi_profile; |
399
|
|
|
|
|
|
|
}; |
400
|
|
|
|
|
|
|
|
401
|
|
|
|
|
|
|
|
402
|
|
|
|
|
|
|
=head2 get_dbi_profile |
403
|
|
|
|
|
|
|
|
404
|
|
|
|
|
|
|
$dbi_profile = $core->get_dbi_profile( $dbi_profile_name ); |
405
|
|
|
|
|
|
|
@dbi_profiles = $core->get_dbi_profile( '*' ); |
406
|
|
|
|
|
|
|
|
407
|
|
|
|
|
|
|
Returns a reference to the DBI Profile object that attached to the $core with the given name. |
408
|
|
|
|
|
|
|
If $dbi_profile_name is undef then it defaults to "main". |
409
|
|
|
|
|
|
|
Returns undef if there's no profile with that name atached. |
410
|
|
|
|
|
|
|
If $dbi_profile_name is 'C<*>' then it returns all attached profiles. |
411
|
|
|
|
|
|
|
See L. |
412
|
|
|
|
|
|
|
|
413
|
|
|
|
|
|
|
=cut |
414
|
|
|
|
|
|
|
|
415
|
|
|
|
|
|
|
sub get_dbi_profile { |
416
|
55
|
|
|
55
|
1
|
798
|
my ($self, $name) = @_; |
417
|
55
|
50
|
|
|
|
167
|
my $dbi_handles = $self->{dbi_handles_all} |
418
|
|
|
|
|
|
|
or return; |
419
|
|
|
|
|
|
|
# we take care to avoid auto-viv here |
420
|
55
|
|
100
|
|
|
195
|
my $dbh = $dbi_handles->{ $name || 'main' }; |
421
|
55
|
100
|
|
|
|
269
|
return $dbh->{Profile} if $dbh; |
422
|
13
|
100
|
66
|
|
|
120
|
return unless $name && $name eq '*'; |
423
|
9
|
50
|
|
|
|
27
|
croak "get_dbi_profile('*') called in scalar context" unless wantarray; |
424
|
10
|
50
|
|
|
|
92
|
return map { |
425
|
9
|
|
|
|
|
30
|
($_->{Profile}) ? ($_->{Profile}) : () |
426
|
|
|
|
|
|
|
} values %$dbi_handles; |
427
|
|
|
|
|
|
|
} |
428
|
|
|
|
|
|
|
|
429
|
|
|
|
|
|
|
|
430
|
|
|
|
|
|
|
=head2 profile_as_text |
431
|
|
|
|
|
|
|
|
432
|
|
|
|
|
|
|
$core->profile_as_text(); |
433
|
|
|
|
|
|
|
$core->profile_as_text( $dbi_profile_name ); |
434
|
|
|
|
|
|
|
$core->profile_as_text( $dbi_profile_name, { |
435
|
|
|
|
|
|
|
path => [ $self->{profile_name} ], |
436
|
|
|
|
|
|
|
format => '%1$s: dur=%11$f count=%10$d (max=%14$f avg=%2$f)'."\n", |
437
|
|
|
|
|
|
|
separator => ">", |
438
|
|
|
|
|
|
|
} ); |
439
|
|
|
|
|
|
|
|
440
|
|
|
|
|
|
|
Returns the aggregated data from the specified DBI Profile (default "main") formatted as a string. |
441
|
|
|
|
|
|
|
Calls L to get the DBI Profile, then calls the C method on the profile. |
442
|
|
|
|
|
|
|
See L for more details of the parameters. |
443
|
|
|
|
|
|
|
|
444
|
|
|
|
|
|
|
In list context it returns one item per profile leaf node, in scalar context |
445
|
|
|
|
|
|
|
they're concatenated into a single string. Returns undef if the named DBI |
446
|
|
|
|
|
|
|
Profile doesn't exist. |
447
|
|
|
|
|
|
|
|
448
|
|
|
|
|
|
|
=cut |
449
|
|
|
|
|
|
|
|
450
|
|
|
|
|
|
|
sub profile_as_text { |
451
|
17
|
|
|
17
|
1
|
2393
|
my $self = shift; |
452
|
17
|
|
|
|
|
23
|
my $name = shift; |
453
|
17
|
|
50
|
|
|
90
|
my $default_args = $self->{profile_as_text_args} || {}; |
454
|
17
|
100
|
|
|
|
50
|
my %args = (%$default_args, %{ shift || {} }); |
|
17
|
|
|
|
|
96
|
|
455
|
|
|
|
|
|
|
|
456
|
17
|
|
50
|
|
|
125
|
$args{path} ||= [ $self->{profile_name} ]; |
457
|
17
|
|
100
|
|
|
81
|
$args{format} ||= '%1$s: dur=%11$f count=%10$d (max=%14$f avg=%2$f)'."\n"; |
458
|
17
|
|
100
|
|
|
78
|
$args{separator} ||= ">"; |
459
|
|
|
|
|
|
|
|
460
|
17
|
100
|
|
|
|
45
|
my $dbi_profile = $self->get_dbi_profile($name) or return; |
461
|
15
|
|
|
|
|
74
|
return $dbi_profile->as_text(\%args); |
462
|
|
|
|
|
|
|
} |
463
|
|
|
|
|
|
|
|
464
|
|
|
|
|
|
|
|
465
|
|
|
|
|
|
|
=head2 reset_profile_data |
466
|
|
|
|
|
|
|
|
467
|
|
|
|
|
|
|
$core->reset_profile_data( $dbi_profile_name ); |
468
|
|
|
|
|
|
|
|
469
|
|
|
|
|
|
|
Resets (discards) DBI Profile data and resets the period count to 0. |
470
|
|
|
|
|
|
|
If $dbi_profile_name is false then it defaults to "main". |
471
|
|
|
|
|
|
|
If $dbi_profile_name is "*" then all attached profiles are reset. |
472
|
|
|
|
|
|
|
Returns a list of the affected DBI::Profile objects. |
473
|
|
|
|
|
|
|
|
474
|
|
|
|
|
|
|
=cut |
475
|
|
|
|
|
|
|
|
476
|
|
|
|
|
|
|
sub reset_profile_data { |
477
|
16
|
|
|
16
|
1
|
12025
|
my ($self, $dbi_profile_name) = @_; |
478
|
16
|
|
|
|
|
61
|
my @dbi_profiles = $self->get_dbi_profile($dbi_profile_name); |
479
|
16
|
|
|
|
|
120
|
$_->empty for @dbi_profiles; |
480
|
16
|
|
|
|
|
150
|
$self->{period_count} = 0; |
481
|
16
|
|
|
|
|
158
|
return @dbi_profiles; |
482
|
|
|
|
|
|
|
} |
483
|
|
|
|
|
|
|
|
484
|
|
|
|
|
|
|
|
485
|
|
|
|
|
|
|
sub _visit_nodes { # depth first with lexical ordering |
486
|
6
|
|
|
6
|
|
10
|
my ($self, $node, $path, $sub) = @_; |
487
|
6
|
50
|
|
|
|
12
|
croak "No sub ref given" unless ref $sub eq 'CODE'; |
488
|
6
|
50
|
|
|
|
13
|
return unless $node; |
489
|
6
|
|
100
|
|
|
11
|
$path ||= []; |
490
|
6
|
100
|
|
|
|
14
|
if (ref $node eq 'HASH') { # recurse |
491
|
4
|
|
|
|
|
8
|
$path = [ @$path, undef ]; |
492
|
5
|
|
|
|
|
9
|
return map { |
493
|
4
|
|
|
|
|
14
|
$path->[-1] = $_; |
494
|
5
|
50
|
|
|
|
28
|
($node->{$_}) ? $self->_visit_nodes($node->{$_}, $path, $sub) : () |
495
|
|
|
|
|
|
|
} sort keys %$node; |
496
|
|
|
|
|
|
|
} |
497
|
2
|
|
|
|
|
4
|
return $sub->($node, $path); |
498
|
|
|
|
|
|
|
} |
499
|
|
|
|
|
|
|
|
500
|
|
|
|
|
|
|
|
501
|
|
|
|
|
|
|
=head2 visit_profile_nodes |
502
|
|
|
|
|
|
|
|
503
|
|
|
|
|
|
|
$core->visit_profile_nodes( $dbi_profile_name, sub { ... } ) |
504
|
|
|
|
|
|
|
|
505
|
|
|
|
|
|
|
Calls the given subroutine for each leaf node in the named DBI Profile. |
506
|
|
|
|
|
|
|
The name defaults to "main". If $dbi_profile_name is "*" then the leafs nodes |
507
|
|
|
|
|
|
|
in all the attached profiles are visited. |
508
|
|
|
|
|
|
|
|
509
|
|
|
|
|
|
|
=cut |
510
|
|
|
|
|
|
|
|
511
|
|
|
|
|
|
|
sub visit_profile_nodes { |
512
|
1
|
|
|
1
|
1
|
3
|
my ($self, $dbi_profile_name, $sub) = @_; |
513
|
1
|
|
|
|
|
3
|
my @dbi_profiles = $self->get_dbi_profile($dbi_profile_name); |
514
|
1
|
|
|
|
|
3
|
for my $dbi_profile (@dbi_profiles) { |
515
|
1
|
50
|
|
|
|
4
|
my $data = $dbi_profile->{Data} |
516
|
|
|
|
|
|
|
or next; |
517
|
1
|
|
|
|
|
5
|
$self->_visit_nodes($data, undef, $sub) |
518
|
|
|
|
|
|
|
} |
519
|
1
|
|
|
|
|
3
|
return; |
520
|
|
|
|
|
|
|
} |
521
|
|
|
|
|
|
|
|
522
|
|
|
|
|
|
|
|
523
|
|
|
|
|
|
|
=head2 propagate_period_count |
524
|
|
|
|
|
|
|
|
525
|
|
|
|
|
|
|
$core->propagate_period_count( $dbi_profile_name ) |
526
|
|
|
|
|
|
|
|
527
|
|
|
|
|
|
|
Sets the count field of all the leaf-nodes in the named DBI Profile to the |
528
|
|
|
|
|
|
|
number of times start_sample_period() has been called since the last flush() or |
529
|
|
|
|
|
|
|
reset_profile_data(). |
530
|
|
|
|
|
|
|
|
531
|
|
|
|
|
|
|
If $dbi_profile_name is "*" then counts in all attached profiles are set. |
532
|
|
|
|
|
|
|
|
533
|
|
|
|
|
|
|
Resets the period count used. |
534
|
|
|
|
|
|
|
|
535
|
|
|
|
|
|
|
Does nothing but return 0 if the the period count is zero. |
536
|
|
|
|
|
|
|
|
537
|
|
|
|
|
|
|
This method is especially useful where the number of sample I are much |
538
|
|
|
|
|
|
|
more relevant than the number of samples. This is typically the case where |
539
|
|
|
|
|
|
|
sample periods correspond to major units of work, such as web requests. |
540
|
|
|
|
|
|
|
Using propagate_period_count() lets you calculate averages based on the count |
541
|
|
|
|
|
|
|
of I instead of samples. |
542
|
|
|
|
|
|
|
|
543
|
|
|
|
|
|
|
Imagine, for example, that you're instrumenting a web application and you have |
544
|
|
|
|
|
|
|
a function that sends a request to some network service and another reads each |
545
|
|
|
|
|
|
|
line of the response. You'd add DashProfiler sampler calls to each function. |
546
|
|
|
|
|
|
|
The number of samples recorded in the leaf node will depends on the number of |
547
|
|
|
|
|
|
|
lines in the response from the network service. You're much more likely to want |
548
|
|
|
|
|
|
|
to know "average total time spent handling the network service per http request" |
549
|
|
|
|
|
|
|
than "average time spent in a network service related function". |
550
|
|
|
|
|
|
|
|
551
|
|
|
|
|
|
|
This method is typically called just before a flush(), often via C. |
552
|
|
|
|
|
|
|
|
553
|
|
|
|
|
|
|
=cut |
554
|
|
|
|
|
|
|
|
555
|
|
|
|
|
|
|
sub propagate_period_count { |
556
|
3
|
|
|
3
|
1
|
1631
|
my ($self, $dbi_profile_name) = @_; |
557
|
|
|
|
|
|
|
# force count of all nodes to be count of periods instead of samples |
558
|
3
|
100
|
|
|
|
12
|
my $count = $self->{period_count} |
559
|
|
|
|
|
|
|
or return 0; |
560
|
1
|
|
|
|
|
3
|
warn "propagate_period_count $self->{profile_name} count $count\n" if DEBUG(); |
561
|
|
|
|
|
|
|
# force count of all nodes to be count of periods |
562
|
1
|
50
|
|
2
|
|
9
|
$self->visit_profile_nodes($dbi_profile_name, sub { return unless ref $_[0] eq 'ARRAY'; $_[0]->[0] = $count }); |
|
2
|
|
|
|
|
6
|
|
|
2
|
|
|
|
|
13
|
|
563
|
1
|
|
|
|
|
5
|
return $count; |
564
|
|
|
|
|
|
|
} |
565
|
|
|
|
|
|
|
|
566
|
|
|
|
|
|
|
|
567
|
|
|
|
|
|
|
=head2 flush |
568
|
|
|
|
|
|
|
|
569
|
|
|
|
|
|
|
$core->flush() |
570
|
|
|
|
|
|
|
$core->flush( $dbi_profile_name ) |
571
|
|
|
|
|
|
|
|
572
|
|
|
|
|
|
|
Calls the C code reference, if set, passing it $core and the |
573
|
|
|
|
|
|
|
$dbi_profile_name augument (which is typically undef). If the C |
574
|
|
|
|
|
|
|
code returns a non-empty list then flush() does nothing more except return that |
575
|
|
|
|
|
|
|
list. |
576
|
|
|
|
|
|
|
|
577
|
|
|
|
|
|
|
If C wasn't set, or it returned an empty list, then the flush_to_disk() |
578
|
|
|
|
|
|
|
method is called for the named DBI Profile (defaults to "main", use "*" for all). |
579
|
|
|
|
|
|
|
In this case flush() returns a list of the DBI::Profile objects flushed. |
580
|
|
|
|
|
|
|
|
581
|
|
|
|
|
|
|
=cut |
582
|
|
|
|
|
|
|
|
583
|
|
|
|
|
|
|
|
584
|
|
|
|
|
|
|
sub flush { |
585
|
2
|
|
|
2
|
1
|
7
|
my ($self, $dbi_profile_name) = @_; |
586
|
2
|
100
|
|
|
|
9
|
if (my $flush_hook = $self->{flush_hook}) { |
587
|
|
|
|
|
|
|
# if flush_hook returns true then don't call flush_to_disk |
588
|
1
|
|
|
|
|
4
|
my @ret = $flush_hook->($self, $dbi_profile_name); |
589
|
1
|
50
|
|
|
|
6
|
return @ret if @ret; |
590
|
|
|
|
|
|
|
# else fall through |
591
|
|
|
|
|
|
|
} |
592
|
1
|
|
|
|
|
3
|
my @dbi_profiles = $self->get_dbi_profile($dbi_profile_name); |
593
|
1
|
|
|
|
|
6
|
$_->flush_to_disk for (@dbi_profiles); |
594
|
1
|
|
|
|
|
16
|
return @dbi_profiles; |
595
|
|
|
|
|
|
|
} |
596
|
|
|
|
|
|
|
|
597
|
|
|
|
|
|
|
|
598
|
|
|
|
|
|
|
=head2 flush_if_due |
599
|
|
|
|
|
|
|
|
600
|
|
|
|
|
|
|
$core->flush_if_due() |
601
|
|
|
|
|
|
|
|
602
|
|
|
|
|
|
|
Returns nothing if C was not set. |
603
|
|
|
|
|
|
|
Returns nothing if C was set but insufficient time has passed since |
604
|
|
|
|
|
|
|
the last call to flush_if_due(). |
605
|
|
|
|
|
|
|
Otherwise notes the time the next flush will be due, and calls C. |
606
|
|
|
|
|
|
|
|
607
|
|
|
|
|
|
|
=cut |
608
|
|
|
|
|
|
|
|
609
|
|
|
|
|
|
|
sub flush_if_due { |
610
|
1
|
|
|
1
|
1
|
1187
|
my ($self) = @_; |
611
|
1
|
50
|
|
|
|
4
|
return unless $self->{flush_interval}; |
612
|
1
|
50
|
|
|
|
14
|
return if time() < $self->{flush_due_at_time}; |
613
|
0
|
|
|
|
|
0
|
$self->{flush_due_at_time} = time() + $self->{flush_interval}; |
614
|
0
|
|
|
|
|
0
|
return $self->flush(); |
615
|
|
|
|
|
|
|
} |
616
|
|
|
|
|
|
|
|
617
|
|
|
|
|
|
|
|
618
|
|
|
|
|
|
|
=head2 has_profile_data |
619
|
|
|
|
|
|
|
|
620
|
|
|
|
|
|
|
$bool = $core->has_profile_data |
621
|
|
|
|
|
|
|
$bool = $core->has_profile_data( $dbi_profile_name ) |
622
|
|
|
|
|
|
|
|
623
|
|
|
|
|
|
|
Returns true if the named DBI Profile (default "main") contains any profile data. |
624
|
|
|
|
|
|
|
|
625
|
|
|
|
|
|
|
=cut |
626
|
|
|
|
|
|
|
|
627
|
|
|
|
|
|
|
sub has_profile_data { |
628
|
9
|
|
|
9
|
1
|
21
|
my ($self, $dbi_profile_name) = @_; |
629
|
9
|
50
|
|
|
|
29
|
my @dbi_profiles = $self->get_dbi_profile($dbi_profile_name) |
630
|
|
|
|
|
|
|
or return undef; ## no critic |
631
|
9
|
100
|
100
|
|
|
25
|
keys %{$_->{Data}||{}} && return 1 for (@dbi_profiles); |
|
10
|
|
|
|
|
91
|
|
632
|
8
|
|
|
|
|
176
|
return 0; |
633
|
|
|
|
|
|
|
} |
634
|
|
|
|
|
|
|
|
635
|
|
|
|
|
|
|
|
636
|
|
|
|
|
|
|
=head2 start_sample_period |
637
|
|
|
|
|
|
|
|
638
|
|
|
|
|
|
|
$core->start_sample_period |
639
|
|
|
|
|
|
|
|
640
|
|
|
|
|
|
|
Marks the start of a series of related samples, e.g, within one http request. |
641
|
|
|
|
|
|
|
|
642
|
|
|
|
|
|
|
If end_sample_period() has not been called for this core since the last |
643
|
|
|
|
|
|
|
start_sample_period() then the value of the C attribute |
644
|
|
|
|
|
|
|
determines the actions taken: |
645
|
|
|
|
|
|
|
|
646
|
|
|
|
|
|
|
0 = restart the period, silently |
647
|
|
|
|
|
|
|
1 = restart the period and issue a warning (this is the default) |
648
|
|
|
|
|
|
|
2 = continue the current period, silently |
649
|
|
|
|
|
|
|
3 = continue the current period and issue a warning |
650
|
|
|
|
|
|
|
4 = call end_sample_period(), silently |
651
|
|
|
|
|
|
|
5 = call end_sample_period() and issue a warning |
652
|
|
|
|
|
|
|
|
653
|
|
|
|
|
|
|
If the value is a CODE ref then it's called (and passed $core) and the return value used. |
654
|
|
|
|
|
|
|
|
655
|
|
|
|
|
|
|
Resets the C attribute to zero. |
656
|
|
|
|
|
|
|
Sets C to the current dbi_time(). |
657
|
|
|
|
|
|
|
If C is enabled then the period_summary DBI Profile is enabled and reset. |
658
|
|
|
|
|
|
|
|
659
|
|
|
|
|
|
|
See also L, the C option, and L. |
660
|
|
|
|
|
|
|
|
661
|
|
|
|
|
|
|
=cut |
662
|
|
|
|
|
|
|
|
663
|
|
|
|
|
|
|
sub start_sample_period { |
664
|
7
|
|
|
7
|
1
|
2884
|
my $self = shift; |
665
|
|
|
|
|
|
|
# marks the start of a series of related samples, e.g, within one http request |
666
|
|
|
|
|
|
|
# see end_sample_period() |
667
|
7
|
50
|
|
|
|
31
|
if ($self->{period_start_time}) { |
668
|
0
|
0
|
|
|
|
0
|
if (my $strictness = $self->{period_strict_start}) { |
669
|
0
|
0
|
|
|
|
0
|
$strictness = $strictness->($self) if ref $strictness eq 'CODE'; |
670
|
0
|
0
|
|
|
|
0
|
carp "start_sample_period() called for $self->{profile_name} without preceeding end_sample_period()" |
671
|
|
|
|
|
|
|
if $strictness & 0x01; |
672
|
|
|
|
|
|
|
return |
673
|
0
|
0
|
|
|
|
0
|
if $strictness & 0x02; |
674
|
0
|
0
|
|
|
|
0
|
$self->end_sample_period() |
675
|
|
|
|
|
|
|
if $strictness & 0x04; |
676
|
|
|
|
|
|
|
} |
677
|
|
|
|
|
|
|
} |
678
|
7
|
100
|
|
|
|
93
|
if (my $period_summary_h = $self->{dbi_handles_all}{period_summary}) { |
679
|
|
|
|
|
|
|
# ensure period_summary_h dbi profile will receive samples |
680
|
2
|
|
|
|
|
6
|
$self->{dbi_handles_active}{period_summary} = $period_summary_h; |
681
|
2
|
|
|
|
|
11
|
$period_summary_h->{Profile}->empty; # start period empty |
682
|
|
|
|
|
|
|
} |
683
|
7
|
|
|
|
|
20
|
$self->{period_accumulated} = 0; |
684
|
7
|
|
|
|
|
23
|
$self->{period_start_time} = dbi_time(); |
685
|
7
|
|
|
|
|
16
|
return; |
686
|
|
|
|
|
|
|
} |
687
|
|
|
|
|
|
|
|
688
|
|
|
|
|
|
|
|
689
|
|
|
|
|
|
|
=head2 end_sample_period |
690
|
|
|
|
|
|
|
|
691
|
|
|
|
|
|
|
$core->end_sample_period |
692
|
|
|
|
|
|
|
|
693
|
|
|
|
|
|
|
Marks the end of a series of related samples, e.g, within one http request. |
694
|
|
|
|
|
|
|
|
695
|
|
|
|
|
|
|
If start_sample_period() has not been called for this core since the last |
696
|
|
|
|
|
|
|
end_sample_period() (or the start of the script) then the value of the |
697
|
|
|
|
|
|
|
C attribute determines the actions taken: |
698
|
|
|
|
|
|
|
|
699
|
|
|
|
|
|
|
0 = do nothing, silently (this is the default) |
700
|
|
|
|
|
|
|
1 = do nothing but warn |
701
|
|
|
|
|
|
|
2 = call start_sample_period(), silently |
702
|
|
|
|
|
|
|
3 = call start_sample_period() and warn |
703
|
|
|
|
|
|
|
|
704
|
|
|
|
|
|
|
If the value is a CODE ref then it's called (and passed $core) and the return value used. |
705
|
|
|
|
|
|
|
If start_sample_period() isn't called then end_sample_period() just returns. |
706
|
|
|
|
|
|
|
|
707
|
|
|
|
|
|
|
The C attribute is incremented. |
708
|
|
|
|
|
|
|
|
709
|
|
|
|
|
|
|
If C is enabled then a sample is added with a duration |
710
|
|
|
|
|
|
|
caclulated to be the time since start_sample_period() was called to now, minus |
711
|
|
|
|
|
|
|
the time accumulated by samples since start_sample_period() was called. |
712
|
|
|
|
|
|
|
|
713
|
|
|
|
|
|
|
Resets the C attribute to 0. If C is |
714
|
|
|
|
|
|
|
enabled then the C DBI Profile is disabled and returned, else |
715
|
|
|
|
|
|
|
undef is returned. |
716
|
|
|
|
|
|
|
|
717
|
|
|
|
|
|
|
See also L, C and L. |
718
|
|
|
|
|
|
|
|
719
|
|
|
|
|
|
|
=cut |
720
|
|
|
|
|
|
|
|
721
|
|
|
|
|
|
|
sub end_sample_period { |
722
|
7
|
|
|
7
|
1
|
1000216
|
my $self = shift; |
723
|
|
|
|
|
|
|
|
724
|
7
|
50
|
|
|
|
33
|
if (not $self->{period_start_time}) { |
725
|
0
|
0
|
|
|
|
0
|
if (my $strictness = $self->{period_strict_end}) { |
726
|
0
|
0
|
|
|
|
0
|
$strictness = $strictness->($self) if ref $strictness eq 'CODE'; |
727
|
0
|
0
|
|
|
|
0
|
carp "end_sample_period() called for $self->{profile_name} without preceeding start_sample_period()" |
728
|
|
|
|
|
|
|
if $strictness & 0x01; |
729
|
0
|
0
|
|
|
|
0
|
$self->start_sample_period() |
730
|
|
|
|
|
|
|
if $strictness & 0x02; |
731
|
|
|
|
|
|
|
} |
732
|
|
|
|
|
|
|
# return if we didn't start a period |
733
|
0
|
0
|
|
|
|
0
|
return if not $self->{period_start_time}; |
734
|
|
|
|
|
|
|
} |
735
|
|
|
|
|
|
|
|
736
|
7
|
|
|
|
|
14
|
$self->{period_count}++; |
737
|
|
|
|
|
|
|
|
738
|
|
|
|
|
|
|
# disconnect period_summary dbi profile from receiving any more samples |
739
|
7
|
|
|
|
|
23
|
my $period_summary_dbh = delete $self->{dbi_handles_active}{period_summary}; |
740
|
7
|
|
|
|
|
12
|
my $period_summary_profile = $period_summary_dbh->{Profile}; |
741
|
|
|
|
|
|
|
|
742
|
7
|
100
|
|
|
|
26
|
if (my $exclusive_sampler = $self->{exclusive_sampler}) { |
743
|
|
|
|
|
|
|
# Calculate how much time between $self->{period_start_time} and now |
744
|
|
|
|
|
|
|
# is not accounted for by $self->{period_accumulated}. |
745
|
|
|
|
|
|
|
# Add a sample with the start time forced to be period_start_time |
746
|
|
|
|
|
|
|
# shifted forward by the accumulated sample durations + sampling overheads. |
747
|
|
|
|
|
|
|
# This accounts for all the time between start_sample_period and |
748
|
|
|
|
|
|
|
# end_sample_period that hasn't been accounted for by normal samples. |
749
|
|
|
|
|
|
|
|
750
|
|
|
|
|
|
|
# calculate overhead of taking samples |
751
|
4
|
|
|
|
|
5
|
my $overhead; |
752
|
4
|
50
|
|
|
|
10
|
if ($period_summary_profile) { |
753
|
|
|
|
|
|
|
# if period_summary is enabled then we can use the count of |
754
|
|
|
|
|
|
|
# samples this period to scale the overhead correctly |
755
|
0
|
|
|
|
|
0
|
dbi_profile_merge(my $total=[], $period_summary_profile->{Data}); |
756
|
|
|
|
|
|
|
# scale overhead by number of samples in period |
757
|
0
|
|
|
|
|
0
|
$overhead = $sample_overhead_time * $total->[0]; |
758
|
|
|
|
|
|
|
} |
759
|
|
|
|
|
|
|
else { |
760
|
|
|
|
|
|
|
# if period_summary is not enabled then we can't do much |
761
|
4
|
|
|
|
|
8
|
$overhead = $sample_overhead_time; |
762
|
|
|
|
|
|
|
} |
763
|
|
|
|
|
|
|
|
764
|
4
|
|
|
|
|
5
|
warn sprintf "%s period end: overhead %.6fs (%.0f * %.6fs)\n", |
765
|
|
|
|
|
|
|
$self->{profile_name}, $overhead, $overhead/$sample_overhead_time, $sample_overhead_time |
766
|
|
|
|
|
|
|
if DEBUG() && DEBUG() >= 3; |
767
|
|
|
|
|
|
|
|
768
|
4
|
|
|
|
|
22
|
$exclusive_sampler->(undef, $self->{period_start_time} + $self->{period_accumulated} + $overhead); |
769
|
|
|
|
|
|
|
|
770
|
|
|
|
|
|
|
# sample gets destroyed, and so counted, immediately. |
771
|
|
|
|
|
|
|
} |
772
|
|
|
|
|
|
|
|
773
|
7
|
|
|
|
|
25
|
$self->{period_start_time} = 0; |
774
|
|
|
|
|
|
|
# $self->{period_accumulated} will be reset by start_sample_period() |
775
|
|
|
|
|
|
|
|
776
|
7
|
|
|
|
|
30
|
return $period_summary_profile; |
777
|
|
|
|
|
|
|
} |
778
|
|
|
|
|
|
|
|
779
|
|
|
|
|
|
|
|
780
|
|
|
|
|
|
|
=head2 period_start_time |
781
|
|
|
|
|
|
|
|
782
|
|
|
|
|
|
|
$time = $core->period_start_time; |
783
|
|
|
|
|
|
|
|
784
|
|
|
|
|
|
|
Returns the time the current sample period was started (typically the time |
785
|
|
|
|
|
|
|
L was called) or 0 if there's no period active. |
786
|
|
|
|
|
|
|
|
787
|
|
|
|
|
|
|
=cut |
788
|
|
|
|
|
|
|
|
789
|
|
|
|
|
|
|
sub period_start_time { |
790
|
3
|
|
|
3
|
1
|
35
|
return shift->{period_start_time}; |
791
|
|
|
|
|
|
|
} |
792
|
|
|
|
|
|
|
|
793
|
|
|
|
|
|
|
|
794
|
|
|
|
|
|
|
=head2 prepare |
795
|
|
|
|
|
|
|
|
796
|
|
|
|
|
|
|
$sampler_code_ref = $core->prepare( $context1 ) |
797
|
|
|
|
|
|
|
$sampler_code_ref = $core->prepare( $context1, $context2 ) |
798
|
|
|
|
|
|
|
$sampler_code_ref = $core->prepare( $context1, $context2, %meta ) |
799
|
|
|
|
|
|
|
|
800
|
|
|
|
|
|
|
$sampler_code_ref->( $context2 ) |
801
|
|
|
|
|
|
|
$sampler_code_ref->( $context2, $start_time ) |
802
|
|
|
|
|
|
|
|
803
|
|
|
|
|
|
|
Returns a reference to a subroutine that will create sampler objects. |
804
|
|
|
|
|
|
|
In effect the prepare() method creates a 'factory'. |
805
|
|
|
|
|
|
|
|
806
|
|
|
|
|
|
|
The sampler objects created by the returned code reference are pre-set to use |
807
|
|
|
|
|
|
|
$context1, and optionally $context2, as their context values. |
808
|
|
|
|
|
|
|
|
809
|
|
|
|
|
|
|
If the appropriate value for C won't be available until the end of |
810
|
|
|
|
|
|
|
the sample you can set $context2 to a code reference. The reference will be |
811
|
|
|
|
|
|
|
executed at the end of the sample. See L. |
812
|
|
|
|
|
|
|
|
813
|
|
|
|
|
|
|
XXX needs more info about %meta - see the code for now, it's not very complex. |
814
|
|
|
|
|
|
|
|
815
|
|
|
|
|
|
|
See L for more information. |
816
|
|
|
|
|
|
|
|
817
|
|
|
|
|
|
|
=cut |
818
|
|
|
|
|
|
|
|
819
|
|
|
|
|
|
|
sub prepare { |
820
|
15
|
|
|
15
|
1
|
1734322
|
my ($self, $context1, $context2, %meta) = @_; |
821
|
|
|
|
|
|
|
# return undef if profile exists but is disabled |
822
|
15
|
50
|
|
|
|
51
|
return undef if $self->{disabled}; ## no critic |
823
|
|
|
|
|
|
|
|
824
|
|
|
|
|
|
|
# return a light wrapper around the profile, containing the context1 |
825
|
15
|
|
33
|
|
|
80
|
my $sample_class = $meta{sample_class} || $self->{sample_class}; |
826
|
|
|
|
|
|
|
# use %meta to carry context info into sample object factory |
827
|
15
|
|
|
|
|
32
|
$meta{_dash_profile} = $self; |
828
|
15
|
|
|
|
|
28
|
$meta{_context1} = $context1; |
829
|
15
|
|
|
|
|
24
|
$meta{_context2} = $context2; |
830
|
|
|
|
|
|
|
# skip method lookup |
831
|
15
|
|
50
|
|
|
157
|
my $coderef = $sample_class->can("new") || "new"; |
832
|
|
|
|
|
|
|
return sub { # closure over $sample_class, %meta and $coderef |
833
|
9213
|
|
|
9213
|
|
6736845
|
$sample_class->$coderef(\%meta, @_) |
834
|
15
|
|
|
|
|
107
|
}; |
835
|
|
|
|
|
|
|
} |
836
|
|
|
|
|
|
|
|
837
|
|
|
|
|
|
|
|
838
|
|
|
|
|
|
|
sub DESTROY { |
839
|
9
|
|
|
9
|
|
46
|
my $self = shift; |
840
|
|
|
|
|
|
|
# global destruction shouldn't be relied upon because often the |
841
|
|
|
|
|
|
|
# dbi profile data will have been already destroyed |
842
|
9
|
50
|
|
|
|
34
|
$self->end_sample_period() if $self->{period_start_time}; |
843
|
9
|
100
|
|
|
|
39
|
$self->flush if $self->has_profile_data("*"); |
844
|
|
|
|
|
|
|
} |
845
|
|
|
|
|
|
|
|
846
|
|
|
|
|
|
|
|
847
|
|
|
|
|
|
|
sub _load_class { |
848
|
25
|
|
|
25
|
|
38
|
my ($class) = @_; |
849
|
|
|
|
|
|
|
## no critic |
850
|
5
|
|
|
5
|
|
46
|
no strict 'refs'; |
|
5
|
|
|
|
|
12
|
|
|
5
|
|
|
|
|
688
|
|
851
|
25
|
100
|
|
|
|
27
|
return 1 if keys %{"$class\::"}; # already loaded |
|
25
|
|
|
|
|
132
|
|
852
|
5
|
|
|
|
|
1260
|
(my $file = $class) =~ s/::/\//g; |
853
|
5
|
|
|
|
|
3057
|
require "$file.pm"; |
854
|
|
|
|
|
|
|
} |
855
|
|
|
|
|
|
|
|
856
|
|
|
|
|
|
|
|
857
|
|
|
|
|
|
|
=head2 DEBUG |
858
|
|
|
|
|
|
|
|
859
|
|
|
|
|
|
|
The DEBUG subroutine is a constant that returns whatever the value of |
860
|
|
|
|
|
|
|
|
861
|
|
|
|
|
|
|
$ENV{DASHPROFILER_CORE_DEBUG} || $ENV{DASHPROFILER_DEBUG} || 0; |
862
|
|
|
|
|
|
|
|
863
|
|
|
|
|
|
|
was when the modle was loaded. |
864
|
|
|
|
|
|
|
|
865
|
|
|
|
|
|
|
=cut |
866
|
|
|
|
|
|
|
|
867
|
|
|
|
|
|
|
|
868
|
|
|
|
|
|
|
|
869
|
|
|
|
|
|
|
# --- DBI::ProfileDumper subclass that doesn't flush_to_disk |
870
|
|
|
|
|
|
|
# Used by period_summary |
871
|
|
|
|
|
|
|
{ |
872
|
|
|
|
|
|
|
package DashProfiler::DumpNowhere; |
873
|
5
|
|
|
5
|
|
43
|
use strict; |
|
5
|
|
|
|
|
55
|
|
|
5
|
|
|
|
|
151
|
|
874
|
5
|
|
|
5
|
|
28
|
use base qw(DBI::ProfileDumper); |
|
5
|
|
|
|
|
9
|
|
|
5
|
|
|
|
|
1696
|
|
875
|
7
|
|
|
7
|
|
133
|
sub flush_to_disk { return } |
876
|
|
|
|
|
|
|
} |
877
|
|
|
|
|
|
|
|
878
|
|
|
|
|
|
|
|
879
|
|
|
|
|
|
|
# --- ultra small 'null' driver for DBI --- |
880
|
|
|
|
|
|
|
# This is really just for the custom dbh DESTROY method below |
881
|
|
|
|
|
|
|
|
882
|
|
|
|
|
|
|
{ |
883
|
|
|
|
|
|
|
package DBD::DashProfiler; |
884
|
|
|
|
|
|
|
our $drh; # holds driver handle once initialised |
885
|
|
|
|
|
|
|
sub driver{ |
886
|
5
|
50
|
|
5
|
0
|
2828
|
return $drh if $drh; |
887
|
5
|
|
|
|
|
12
|
my ($class, $attr) = @_; |
888
|
5
|
|
|
|
|
7
|
$DBD::DashProfiler::db::imp_data_size = 0; |
889
|
5
|
|
|
|
|
8
|
$DBD::DashProfiler::dr::imp_data_size = 0; |
890
|
5
|
|
|
|
|
44
|
return DBI::_new_drh($class."::dr", { |
891
|
|
|
|
|
|
|
Name => 'DashProfiler', Version => $DashProfiler::Core::VERSION, |
892
|
|
|
|
|
|
|
}); |
893
|
|
|
|
|
|
|
} |
894
|
0
|
|
|
0
|
|
0
|
sub CLONE { undef $drh } |
895
|
|
|
|
|
|
|
} |
896
|
|
|
|
|
|
|
{ package DBD::DashProfiler::dr; |
897
|
|
|
|
|
|
|
our $imp_data_size = 0; |
898
|
0
|
|
|
0
|
|
0
|
sub DESTROY { undef } |
899
|
|
|
|
|
|
|
} |
900
|
|
|
|
|
|
|
{ package DBD::DashProfiler::db; |
901
|
|
|
|
|
|
|
our $imp_data_size = 0; |
902
|
5
|
|
|
5
|
|
28
|
use strict; |
|
5
|
|
|
|
|
8
|
|
|
5
|
|
|
|
|
822
|
|
903
|
|
|
|
|
|
|
sub STORE { |
904
|
91
|
|
|
91
|
|
3088
|
my ($dbh, $attrib, $value) = @_; |
905
|
91
|
50
|
|
|
|
308
|
$value = ($value) ? -901 : -900 if $attrib eq 'AutoCommit'; |
|
|
100
|
|
|
|
|
|
906
|
91
|
|
|
|
|
953
|
return $dbh->SUPER::STORE($attrib, $value); |
907
|
|
|
|
|
|
|
} |
908
|
|
|
|
|
|
|
sub DESTROY { |
909
|
10
|
|
|
10
|
|
43
|
my $dbh = shift; |
910
|
10
|
|
|
|
|
23
|
$dbh->{Profile} = undef; # don't profile the DESTROY |
911
|
10
|
|
|
|
|
653
|
return $dbh->SUPER::DESTROY; |
912
|
|
|
|
|
|
|
} |
913
|
|
|
|
|
|
|
} |
914
|
|
|
|
|
|
|
{ package DBD::DashProfiler::st; |
915
|
|
|
|
|
|
|
our $imp_data_size = 0; |
916
|
|
|
|
|
|
|
} |
917
|
|
|
|
|
|
|
# fake the %INC entry so DBI install_driver won't try to load it |
918
|
5
|
|
|
5
|
|
194
|
BEGIN { $INC{"DBD/DashProfiler.pm"} = __FILE__ } |
919
|
|
|
|
|
|
|
|
920
|
|
|
|
|
|
|
|
921
|
|
|
|
|
|
|
|
922
|
|
|
|
|
|
|
1; |
923
|
|
|
|
|
|
|
|
924
|
|
|
|
|
|
|
=head1 AUTHOR |
925
|
|
|
|
|
|
|
|
926
|
|
|
|
|
|
|
DashProfiler by Tim Bunce, L and |
927
|
|
|
|
|
|
|
L |
928
|
|
|
|
|
|
|
|
929
|
|
|
|
|
|
|
=head1 COPYRIGHT |
930
|
|
|
|
|
|
|
|
931
|
|
|
|
|
|
|
The DashProfiler distribution is Copyright (c) 2007-2008 Tim Bunce. Ireland. |
932
|
|
|
|
|
|
|
All rights reserved. |
933
|
|
|
|
|
|
|
|
934
|
|
|
|
|
|
|
You may distribute under the terms of either the GNU General Public |
935
|
|
|
|
|
|
|
License or the Artistic License, as specified in the Perl README file. |
936
|
|
|
|
|
|
|
|
937
|
|
|
|
|
|
|
=cut |
938
|
|
|
|
|
|
|
|