1DBI::Profile(3) User Contributed Perl Documentation DBI::Profile(3)
2
6 DBI::Profile - Performance profiling and benchmarking for the DBI
7
9 The easiest way to enable DBI profiling is to set the DBI_PROFILE envi‐
10 ronment variable to 2 and then run your code as usual:
11 DBI_PROFILE=2 prog.pl
13 This will profile your program and then output a textual summary
15 grouped by query when the program exits. You can also enable profiling
16 by setting the Profile attribute of any DBI handle:
17 $dbh->{Profile} = 2;
19 Then the summary will be printed when the handle is destroyed.
21 Many other values apart from are possible - see "ENABLING A PROFILE"
23 below.
24
26 The DBI::Profile module provides a simple interface to collect and
27 report performance and benchmarking data from the DBI.
28 For a more elaborate interface, suitable for larger programs, see
30 DBI::ProfileDumper and dbiprof. For Apache/mod_perl applications see
31 DBI::ProfileDumper::Apache.
32
34 Performance data collection for the DBI is built around several con‐
35 cepts which are important to understand clearly.
36 Method Dispatch
38 Every method call on a DBI handle passes through a single 'dis‐
39 patch' function which manages all the common aspects of DBI method
40 calls, such as handling the RaiseError attribute.
41 Data Collection
43 If profiling is enabled for a handle then the dispatch code takes a
44 high-resolution timestamp soon after it is entered. Then, after
45 calling the appropriate method and just before returning, it takes
46 another high-resolution timestamp and calls a function to record
47 the information. That function is passed the two timestamps plus
48 the DBI handle and the name of the method that was called. That
49 data about a single DBI method call is called a profile sample.
50 Data Filtering
52 If the method call was invoked by the DBI or by a driver then the
53 call is ignored for profiling because the time spent will be
54 accounted for by the original 'outermost' call for your code.
55 For example, the calls that the selectrow_arrayref() method makes
57 to prepare() and execute() etc. are not counted individually
58 because the time spent in those methods is going to be allocated to
59 the selectrow_arrayref() method when it returns. If this was not
60 done then it would be very easy to double count time spent inside
61 the DBI.
62 Data Storage Tree
64 The profile data is accumulated as 'leaves on a tree'. The 'path'
65 through the branches of the tree to a particular leaf is determined
66 dynamically for each sample. This is a key feature of DBI profili‐
67 ing.
68 For each profiled method call the DBI walks along the Path and uses
70 each value in the Path to step into and grow the Data tree.
71 For example, if the Path is
73 [ 'foo', 'bar', 'baz' ]
75 then the new profile sample data will be merged into the tree at
77 $h->{Profile}->{Data}->{foo}->{bar}->{baz}
79 But it's not very useful to merge all the call data into one leaf
81 node (except to get an overall 'time spent inside the DBI' total).
82 It's more common to want the Path to include dynamic values such as
83 the current statement text and/or the name of the method called to
84 show what the time spent inside the DBI was for.
85 The Path can contain some 'magic cookie' values that are automati‐
87 cally replaced by corresponding dynamic values when they're used.
88 These magic cookies always start with a punctuation character.
89 For example a value of '"!MethodName"' in the Path causes the cor‐
91 responding entry in the Data to be the name of the method that was
92 called. For example, if the Path was:
93 [ 'foo', '!MethodName', 'selectall_arrayref' ]
95 and the selectall_arrayref() method was called, then the profile
97 sample data for that call will be merged into the tree at:
98 $h->{Profile}->{Data}->{foo}->{selectall_arrayref}->{bar}
100 Profile Data
102 Profile data is stored at the 'leaves' of the tree as references to
103 an array of numeric values. For example:
104 [
106 106, # 0: count of samples at this node
107 0.0312958955764771, # 1: total duration
108 0.000490069389343262, # 2: first duration
109 0.000176072120666504, # 3: shortest duration
110 0.00140702724456787, # 4: longest duration
111 1023115819.83019, # 5: time of first sample
112 1023115819.86576, # 6: time of last sample
113 ]
114 After the first sample, later samples always update elements 0, 1,
116 and 6, and may update 3 or 4 depending on the duration of the sam‐
117 pled call.
118
120 Profiling is enabled for a handle by assigning to the Profile
121 attribute. For example:
122 $h->{Profile} = DBI::Profile->new();
124 The Profile attribute holds a blessed reference to a hash object that
126 contains the profile data and attributes relating to it.
127 The class the Profile object is blessed into is expected to provide at
129 least a DESTROY method which will dump the profile data to the DBI
130 trace file handle (STDERR by default).
131 All these examples have the same effect as each other:
133 $h->{Profile} = 0;
135 $h->{Profile} = "/DBI::Profile";
136 $h->{Profile} = DBI::Profile->new();
137 $h->{Profile} = {};
138 $h->{Profile} = { Path => [] };
139 Similarly, these examples have the same effect as each other:
141 $h->{Profile} = 6;
143 $h->{Profile} = "6/DBI::Profile";
144 $h->{Profile} = "!Statement:!MethodName/DBI::Profile";
145 $h->{Profile} = { Path => [ '!Statement', '!MethodName' ] };
146 If a non-blessed hash reference is given then the DBI::Profile module
148 is automatically "require"'d and the reference is blessed into that
149 class.
150 If a string is given then it is processed like this:
152 ($path, $module, $args) = split /\//, $string, 3
154 @path = split /:/, $path
156 @args = split /:/, $args
157 eval "require $module" if $module
159 $module ⎪⎪= "DBI::Profile"
160 $module->new( Path => \@Path, @args )
162 So the first value is used to select the Path to be used (see below).
164 The second value, if present, is used as the name of a module which
165 will be loaded and it's "new" method called. If not present it defaults
166 to DBI::Profile. Any other values are passed as arguments to the "new"
167 method. For example: ""2/DBIx::OtherProfile/Foo:42"".
168 Numbers can be used as a shorthand way to enable common Path values.
170 The simplest way to explain how the values are interpreted is to show
171 the code:
172 push @Path, "DBI" if $path_elem & 0x01;
174 push @Path, "!Statement" if $path_elem & 0x02;
175 push @Path, "!MethodName" if $path_elem & 0x04;
176 push @Path, "!MethodClass" if $path_elem & 0x08;
177 push @Path, "!Caller2" if $path_elem & 0x10;
178 So "2" is the same as "!Statement" and "6" (2+4) is the same as
180 "!Statement:!Method". Those are the two most commonly used values.
181 Using a negative number will reverse the path. Thus "-6" will group by
182 method name then statement.
183 The spliting and parsing of string values assigned to the Profile
185 attribute may seem a little odd, but there's a good reason for it.
186 Remember that attributes can be embedded in the Data Source Name string
187 which can be passed in to a script as a parameter. For example:
188 dbi:DriverName(Profile=>2):dbname
190 dbi:DriverName(Profile=>{Username}:!Statement/MyProfiler/Foo:42):dbname
191 And also, if the "DBI_PROFILE" environment variable is set then The DBI
193 arranges for every driver handle to share the same profile object. When
194 perl exits a single profile summary will be generated that reflects (as
195 nearly as practical) the total use of the DBI by the application.
196
198 The DBI core expects the Profile attribute value to be a hash reference
199 and if the following values don't exist it will create them as needed:
200 Data
202 A reference to a hash containing the collected profile data.
204 Path
206 The Path value is a reference to an array. Each element controls the
208 value to use at the corresponding level of the profile Data tree.
209 The elements of Path array can be one of the following types:
211 Special Constant
213 !Statement
214 Use the current Statement text. Typically that's the value of the
216 Statement attribute for the handle the method was called with. Some
217 methods, like commit() and rollback(), are unrelated to a particu‐
218 lar statement. For those methods !Statement records an empty
219 string.
220 For statement handles this is always simply the string that was
222 given to prepare() when the handle was created. For database han‐
223 dles this is the statement that was last prepared or executed on
224 that database handle. That can lead to a little 'fuzzyness'
225 because, for example, calls to the quote() method to build a new
226 statement will typically be associated with the previous statement.
227 In practice this isn't a significant issue and the dynamic Path
228 mechanism can be used to setup your own rules.
229 !MethodName
231 Use the name of the DBI method that the profile sample relates to.
233 !MethodClass
235 Use the fully qualified name of the DBI method, including the pack‐
237 age, that the profile sample relates to. This shows you where the
238 method was implemented. For example:
239 'DBD::_::db::selectrow_arrayref' =>
241 0.022902s
242 'DBD::mysql::db::selectrow_arrayref' =>
243 2.244521s / 99 = 0.022445s avg (first 0.022813s, min 0.022051s, max 0.028932s)
244 The "DBD::_::db::selectrow_arrayref" shows that the driver has
246 inherited the selectrow_arrayref method provided by the DBI.
247 But you'll note that there is only one call to DBD::_::db::selec‐
249 trow_arrayref but another 99 to DBD::mysql::db::selectrow_arrayref.
250 Currently the first call Pern't record the true location. That may
251 change.
252 !Caller
254 Use a string showing the filename and line number of the code call‐
256 ing the method.
257 !Caller2
259 Use a string showing the filename and line number of the code call‐
261 ing the method, as for !Caller, but also include filename and line
262 number of the code that called that. Calls from DBI:: and DBD::
263 packages are skipped.
264 !File
266 Same as !Caller above except that only the filename is included,
268 not the line number.
269 !File2
271 Same as !Caller2 above except that only the filenames are included,
273 not the line number.
274 Code Reference
276 The subroutine is passed the handle it was called on and the DBI
277 method name. The current Statement is in $_. The statement string
278 should not be modified, so most subs start with "local $_ = $_;".
279 The list of values it returns is used at that point in the Profile
281 Path.
282 The sub can 'veto' (reject) a profile sample by including a refer‐
284 ence to undef in the returned list. That can be useful when you
285 want to only profile statements that match a certain pattern, or
286 only profile certain methods.
287 Subroutine Specifier
289 A Path element that begins with '"&"' is treated as the name of a
290 subroutine in the DBI::ProfileSubs namespace and replaced with the
291 corresponding code reference.
292 Currently this only works when the Path is specified by the
294 "DBI_PROFILE" environment variable.
295 Also, currently, the only subroutine in the DBI::ProfileSubs names‐
297 pace is '&norm_std_n3'. That's a very handy subroutine when profil‐
298 ing code that doesn't use placeholders. See DBI::ProfileSubs for
299 more information.
300 Attribute Specifier
302 A string enclosed in braces, such as '"{Username}"', specifies that
303 the current value of the corresponding database handle attribute
304 should be used at that point in the Path.
305 Other Values
307 Any other values are stringified and used literally.
308 (References, and values that begin with punctuation characters are
310 reserved.)
311 Only the first 100 elements in Path are used.
313 If the value of Path is anything other than an array reference, it is
315 treated as if it was:
316 [ DBI::Profile::!Statement ]
318
320 Report Format
321 The current accumulated profile data can be formatted and output using
323 print $h->{Profile}->format;
325 To discard the profile data and start collecting fresh data you can do:
327 $h->{Profile}->{Data} = undef;
329 The default results format looks like this:
331 DBI::Profile: 0.001015s 42.7% (5 calls) programname @ YYYY-MM-DD HH:MM:SS
333 '' =>
334 0.000024s / 2 = 0.000012s avg (first 0.000015s, min 0.000009s, max 0.000015s)
335 'SELECT mode,size,name FROM table' =>
336 0.000991s / 3 = 0.000330s avg (first 0.000678s, min 0.000009s, max 0.000678s)
337 Which shows the total time spent inside the DBI, with a count of the
339 total number of method calls and the name of the script being run, then
340 a formated version of the profile data tree.
341 If the results are being formated when the perl process is exiting
343 (which is usually the case when the DBI_PROFILE environment variable is
344 used) then the percentage of time the process spent inside the DBI is
345 also shown. If the process is not exiting then the percentage is calcu‐
346 lated using the time between the first and last call to the DBI.
347 In the example above the paths in the tree are only one level deep and
349 use the Statement text as the value (that's the default behaviour).
350 The merged profile data at the 'leaves' of the tree are presented as
352 total time spent, count, average time spent (which is simply total time
353 divided by the count), then the time spent on the first call, the time
354 spent on the fastest call, and finally the time spent on the slowest
355 call.
356 The 'avg', 'first', 'min' and 'max' times are not particularly useful
358 when the profile data path only contains the statement text. Here's an
359 extract of a more detailed example using both statement text and method
360 name in the path:
361 'SELECT mode,size,name FROM table' =>
363 'FETCH' =>
364 0.000076s
365 'fetchrow_hashref' =>
366 0.036203s / 108 = 0.000335s avg (first 0.000490s, min 0.000152s, max 0.002786s)
367 Here you can see the 'avg', 'first', 'min' and 'max' for the 108 calls
369 to fetchrow_hashref() become rather more interesting. Also the data
370 for FETCH just shows a time value because it was only called once.
371 Currently the profile data is output sorted by branch names. That may
373 change in a later version so the leaf nodes are sorted by total time
374 per leaf node.
375 Report Destination
377 The default method of reporting is for the DESTROY method of the Pro‐
379 file object to format the results and write them using:
380 DBI->trace_msg($results, 0); # see $ON_DESTROY_DUMP below
382 to write them to the DBI trace() filehandle (which defaults to STDERR).
384 To direct the DBI trace filehandle to write to a file without enabling
385 tracing the trace() method can be called with a trace level of 0. For
386 example:
387 DBI->trace(0, $filename);
389 The same effect can be achieved without changing the code by setting
391 the "DBI_TRACE" environment variable to "0=filename".
392 The $DBI::Profile::ON_DESTROY_DUMP variable holds a code ref that's
394 called to perform the output of the formatted results. The default
395 value is:
396 $ON_DESTROY_DUMP = sub { DBI->trace_msg($results, 0) };
398 Apart from making it easy to send the dump elsewhere, it can also be
400 useful as a simple way to disable dumping results.
401
403 Child handles inherit a reference to the Profile attribute value of
404 their parent. So if profiling is enabled for a database handle then by
405 default the statement handles created from it all contribute to the
406 same merged profile data tree.
407
409 Recall that "$h-"{Profile}->{Data}> is a reference to the collected
410 data. Either to a 'leaf' array (when the Path is empty, i.e., DBI_PRO‐
411 FILE env var is 1), or a reference to hash containing values that are
412 either further hash references or leaf array references.
413 Sometimes it's useful to be able to summarise some or all of the col‐
415 lected data. The dbi_profile_merge() function can be used to merge
416 leaf node values.
417 dbi_profile_merge
419 use DBI qw(dbi_profile_merge);
421 $time_in_dbi = dbi_profile_merge(my $totals=[], @$leaves);
423 Merges profile data node. Given a reference to a destination array, and
425 zero or more references to profile data, merges the profile data into
426 the destination array. For example:
427 $time_in_dbi = dbi_profile_merge(
429 my $totals=[],
430 [ 10, 0.51, 0.11, 0.01, 0.22, 1023110000, 1023110010 ],
431 [ 15, 0.42, 0.12, 0.02, 0.23, 1023110005, 1023110009 ],
432 );
433 $totals will then contain
435 [ 25, 0.93, 0.11, 0.01, 0.23, 1023110000, 1023110010 ]
437 and $time_in_dbi will be 0.93;
439 For example, to get the time spent 'inside' the DBI during an http
441 request, your logging code run at the end of the request (i.e. mod_perl
442 LogHandler) could use:
443 my $time_in_dbi = 0;
445 if (my $Profile = $dbh->{Profile}) { # if DBI profiling is enabled
446 $time_in_dbi = dbi_profile_merge(my $total=[], $Profile->{Data});
447 $Profile->{Data} = {}; # reset the profile data
448 }
449 If profiling has been enabled then $time_in_dbi will hold the time
451 spent inside the DBI for that handle (and any other handles that share
452 the same profile data) since the last request.
453
455 Using The Path Attribute
456 XXX example to be added later using a selectall_arrayref call
458 XXX nested inside a fetch loop where the first column of the
459 XXX outer loop is bound to the profile Path using
460 XXX bind_column(1, \${ $dbh->{Profile}->{Path}->[0] })
461 XXX so you end up with separate profiles for each loop
462 XXX (patches welcome to add this to the docs :)
463 Adding Your Own Samples
465 The dbi_profile() function can be used to add extra sample data into
467 the profile data tree. For example:
468 use DBI;
470 use DBI::Profile (dbi_profile dbi_time);
471 my $t1 = dbi_time(); # floating point high-resolution time
473 ... execute code you want to profile here ...
475 my $t2 = dbi_time();
477 dbi_profile($h, $statement, $method, $t1, $t2);
478 The $h parameter is the handle the extra profile sample should be asso‐
480 ciated with. The $statement parameter is the string to use where the
481 Path specifies !Statement. If $statement is undef then $h->{Statement}
482 will be used. Similarly $method is the string to use if the Path speci‐
483 fies !MethodName. There is no default value for $method.
484 The $h->{Profile}{Path} attribute is processed by dbi_profile() in the
486 usual way.
487 It is recommended that you keep these extra data samples separate from
489 the DBI profile data samples by using values for $statement and $method
490 that are distinct from any that are likely to appear in the profile
491 data normally.
492
494 Alternate profile modules must subclass DBI::Profile to help ensure
495 they work with future versions of the DBI.
496
498 Applications which generate many different statement strings (typically
499 because they don't use placeholders) and profile with !Statement in the
500 Path (the default) will consume memory in the Profile Data structure
501 for each statement. Use a code ref in the Path to return an edited
502 (simplified) form of the statement.
503 If a method throws an exception itself (not via RaiseError) then it
505 won't be counted in the profile.
506 If a HandleError subroutine throws an exception (rather than returning
508 0 and letting RaiseError do it) then the method call won't be counted
509 in the profile.
510 Time spent in DESTROY is added to the profile of the parent handle.
512 Time spent in DBI->*() methods is not counted. The time spent in the
514 driver connect method, $drh->connect(), when it's called by DBI->con‐
515 nect is counted if the DBI_PROFILE environment variable is set.
516 Time spent fetching tied variables, $DBI::errstr, is counted.
518 Time spent in FETCH for $h->{Profile} is not counted, so getting the
520 profile data doesn't alter it.
521 DBI::PurePerl does not support profiling (though it could in theory).
523 A few platforms don't support the gettimeofday() high resolution time
525 function used by the DBI (and available via the dbi_time() function).
526 In which case you'll get integer resolution time which is mostly use‐
527 less.
528 On Windows platforms the dbi_time() function is limited to millisecond
530 resolution. Which isn't sufficiently fine for our needs, but still much
531 better than integer resolution. This limited resolution means that fast
532 method calls will often register as taking 0 time. And timings in gen‐
533 eral will have much more 'jitter' depending on where within the 'cur‐
534 rent millisecond' the start and and timing was taken.
535 This documentation could be more clear. Probably needs to be reordered
537 to start with several examples and build from there. Trying to explain
538 the concepts first seems painful and to lead to just as many forward
539 references. (Patches welcome!)
540perl v5.8.8 2006-02-07 DBI::Profile(3)