Data¶

A reference to a hash containing the collected profile data.

Path¶

The Path value is a reference to an array. Each element controls the value to use at the corresponding level of the profile Data tree.

If the value of Path is anything other than an array reference, it is treated as if it was:

        [ '!Statement' ]

The elements of Path array can be one of the following types:

Special Constant

!Statement

Use the current Statement text. Typically that's the value of the Statement attribute for the handle the method was called with. Some methods, like commit() and rollback(), are unrelated to a particular statement. For those methods !Statement records an empty string.

For statement handles this is always simply the string that was given to prepare() when the handle was created. For database handles this is the statement that was last prepared or executed on that database handle. That can lead to a little 'fuzzyness' because, for example, calls to the quote() method to build a new statement will typically be associated with the previous statement. In practice this isn't a significant issue and the dynamic Path mechanism can be used to setup your own rules.

!MethodName

Use the name of the DBI method that the profile sample relates to.

!MethodClass

Use the fully qualified name of the DBI method, including the package, that the profile sample relates to. This shows you where the method was implemented. For example:

  'DBD::_::db::selectrow_arrayref' =>
      0.022902s
  'DBD::mysql::db::selectrow_arrayref' =>
      2.244521s / 99 = 0.022445s avg (first 0.022813s, min 0.022051s, max 0.028932s)

The "DBD::_::db::selectrow_arrayref" shows that the driver has inherited the selectrow_arrayref method provided by the DBI.

But you'll note that there is only one call to DBD::_::db::selectrow_arrayref but another 99 to DBD::mysql::db::selectrow_arrayref. Currently the first call doesn't record the true location. That may change.

!Caller

Use a string showing the filename and line number of the code calling the method.

!Caller2

Use a string showing the filename and line number of the code calling the method, as for !Caller, but also include filename and line number of the code that called that. Calls from DBI:: and DBD:: packages are skipped.

!File

Same as !Caller above except that only the filename is included, not the line number.

!File2

Same as !Caller2 above except that only the filenames are included, not the line number.

!Time

Use the current value of time(). Rarely used. See the more useful "!Time~N" below.

!Time~N

Where "N" is an integer. Use the current value of time() but with reduced precision. The value used is determined in this way:

    int( time() / N ) * N

This is a useful way to segregate a profile into time slots. For example:

    [ '!Time~60', '!Statement' ]

Code Reference

The subroutine is passed the handle it was called on and the DBI method name. The current Statement is in $_. The statement string should not be modified, so most subs start with "local $_ = $_;".

The list of values it returns is used at that point in the Profile Path. Any undefined values are treated as the string ""undef"".

The sub can 'veto' (reject) a profile sample by including a reference to undef ("\undef") in the returned list. That can be useful when you want to only profile statements that match a certain pattern, or only profile certain methods.

Subroutine Specifier

A Path element that begins with '"&"' is treated as the name of a subroutine in the DBI::ProfileSubs namespace and replaced with the corresponding code reference.

Currently this only works when the Path is specified by the "DBI_PROFILE" environment variable.

Also, currently, the only subroutine in the DBI::ProfileSubs namespace is '&norm_std_n3'. That's a very handy subroutine when profiling code that doesn't use placeholders. See DBI::ProfileSubs for more information.

Attribute Specifier

A string enclosed in braces, such as '"{Username}"', specifies that the current value of the corresponding database handle attribute should be used at that point in the Path.

Reference to a Scalar

Specifies that the current value of the referenced scalar be used at that point in the Path. This provides an efficient way to get 'contextual' values into your profile.

Other Values

Any other values are stringified and used literally.

(References, and values that begin with punctuation characters are reserved.)

Report Format¶

The current accumulated profile data can be formatted and output using

    print $h->{Profile}->format;

To discard the profile data and start collecting fresh data you can do:

    $h->{Profile}->{Data} = undef;

The default results format looks like this:

  DBI::Profile: 0.001015s 42.7% (5 calls) programname @ YYYY-MM-DD HH:MM:SS
  '' =>
      0.000024s / 2 = 0.000012s avg (first 0.000015s, min 0.000009s, max 0.000015s)
  'SELECT mode,size,name FROM table' =>
      0.000991s / 3 = 0.000330s avg (first 0.000678s, min 0.000009s, max 0.000678s)

Which shows the total time spent inside the DBI, with a count of the total number of method calls and the name of the script being run, then a formatted version of the profile data tree.

If the results are being formatted when the perl process is exiting (which is usually the case when the DBI_PROFILE environment variable is used) then the percentage of time the process spent inside the DBI is also shown. If the process is not exiting then the percentage is calculated using the time between the first and last call to the DBI.

In the example above the paths in the tree are only one level deep and use the Statement text as the value (that's the default behaviour).

The merged profile data at the 'leaves' of the tree are presented as total time spent, count, average time spent (which is simply total time divided by the count), then the time spent on the first call, the time spent on the fastest call, and finally the time spent on the slowest call.

The 'avg', 'first', 'min' and 'max' times are not particularly useful when the profile data path only contains the statement text. Here's an extract of a more detailed example using both statement text and method name in the path:

  'SELECT mode,size,name FROM table' =>
      'FETCH' =>
          0.000076s
      'fetchrow_hashref' =>
          0.036203s / 108 = 0.000335s avg (first 0.000490s, min 0.000152s, max 0.002786s)

Here you can see the 'avg', 'first', 'min' and 'max' for the 108 calls to fetchrow_hashref() become rather more interesting. Also the data for FETCH just shows a time value because it was only called once.

Currently the profile data is output sorted by branch names. That may change in a later version so the leaf nodes are sorted by total time per leaf node.

Report Destination¶

The default method of reporting is for the DESTROY method of the Profile object to format the results and write them using:

    DBI->trace_msg($results, 0);  # see $ON_DESTROY_DUMP below

to write them to the DBI trace() filehandle (which defaults to STDERR). To direct the DBI trace filehandle to write to a file without enabling tracing the trace() method can be called with a trace level of 0. For example:

    DBI->trace(0, $filename);

The same effect can be achieved without changing the code by setting the "DBI_TRACE" environment variable to "0=filename".

The $DBI::Profile::ON_DESTROY_DUMP variable holds a code ref that's called to perform the output of the formatted results. The default value is:

  $ON_DESTROY_DUMP = sub { DBI->trace_msg($results, 0) };

Apart from making it easy to send the dump elsewhere, it can also be useful as a simple way to disable dumping results.

format¶

See "REPORTING".

as_node_path_list¶

  @ary = $dbh->{Profile}->as_node_path_list();
  @ary = $dbh->{Profile}->as_node_path_list($node, $path);

Returns the collected data ($dbh->{Profile}{Data}) restructured into a list of array refs, one for each leaf node in the Data tree. This 'flat' structure is often much simpler for applications to work with.

The first element of each array ref is a reference to the leaf node. The remaining elements are the 'path' through the data tree to that node.

For example, given a data tree like this:

    {key1a}{key2a}[node1]
    {key1a}{key2b}[node2]
    {key1b}{key2a}{key3a}[node3]

The as_node_path_list() method will return this list:

    [ [node1], 'key1a', 'key2a' ]
    [ [node2], 'key1a', 'key2b' ]
    [ [node3], 'key1b', 'key2a', 'key3a' ]

The nodes are ordered by key, depth-first.

The $node argument can be used to focus on a sub-tree. If not specified it defaults to $dbh->{Profile}{Data}.

The $path argument can be used to specify a list of path elements that will be added to each element of the returned list. If not specified it defaults to a ref to an empty array.

as_text¶

  @txt = $dbh->{Profile}->as_text();
  $txt = $dbh->{Profile}->as_text({
      node      => undef,
      path      => [],
      separator => " > ",
      format    => '%1$s: %11$fs / %10$d = %2$fs avg (first %12$fs, min %13$fs, max %14$fs)'."\n";
      sortsub   => sub { ... },
  );

Returns the collected data ($dbh->{Profile}{Data}) reformatted into a list of formatted strings. In scalar context the list is returned as a single concatenated string.

A hashref can be used to pass in arguments, the default values are shown in the example above.

The "node" and <path> arguments are passed to as_node_path_list().

The "separator" argument is used to join the elements of the path for each leaf node.

The "sortsub" argument is used to pass in a ref to a sub that will order the list. The subroutine will be passed a reference to the array returned by as_node_path_list() and should sort the contents of the array in place. The return value from the sub is ignored. For example, to sort the nodes by the second level key you could use:

  sortsub => sub { my $ary=shift; @$ary = sort { $a->[2] cmp $b->[2] } @$ary }

The "format" argument is a "sprintf" format string that specifies the format to use for each leaf node. It uses the explicit format parameter index mechanism to specify which of the arguments should appear where in the string. The arguments to sprintf are:

     1:  path to node, joined with the separator
     2:  average duration (total duration/count)
         (3 thru 9 are currently unused)
    10:  count
    11:  total duration
    12:  first duration
    13:  smallest duration
    14:  largest duration
    15:  time of first call
    16:  time of first call

dbi_profile_merge_nodes¶

  use DBI qw(dbi_profile_merge_nodes);
  $time_in_dbi = dbi_profile_merge_nodes(my $totals=[], @$leaves);

Merges profile data node. Given a reference to a destination array, and zero or more references to profile data, merges the profile data into the destination array. For example:

  $time_in_dbi = dbi_profile_merge_nodes(
      my $totals=[],
      [ 10, 0.51, 0.11, 0.01, 0.22, 1023110000, 1023110010 ],
      [ 15, 0.42, 0.12, 0.02, 0.23, 1023110005, 1023110009 ],
  );

$totals will then contain

  [ 25, 0.93, 0.11, 0.01, 0.23, 1023110000, 1023110010 ]

and $time_in_dbi will be 0.93;

The second argument need not be just leaf nodes. If given a reference to a hash then the hash is recursively searched for leaf nodes and all those found are merged.

For example, to get the time spent 'inside' the DBI during an http request, your logging code run at the end of the request (i.e. mod_perl LogHandler) could use:

  my $time_in_dbi = 0;
  if (my $Profile = $dbh->{Profile}) { # if DBI profiling is enabled
      $time_in_dbi = dbi_profile_merge_nodes(my $total=[], $Profile->{Data});
      $Profile->{Data} = {}; # reset the profile data
  }

If profiling has been enabled then $time_in_dbi will hold the time spent inside the DBI for that handle (and any other handles that share the same profile data) since the last request.

Prior to DBI 1.56 the dbi_profile_merge_nodes() function was called dbi_profile_merge(). That name still exists as an alias.

Using The Path Attribute¶

  XXX example to be added later using a selectall_arrayref call
  XXX nested inside a fetch loop where the first column of the
  XXX outer loop is bound to the profile Path using
  XXX bind_column(1, \${ $dbh->{Profile}->{Path}->[0] })
  XXX so you end up with separate profiles for each loop
  XXX (patches welcome to add this to the docs :)

Adding Your Own Samples¶

The dbi_profile() function can be used to add extra sample data into the profile data tree. For example:

    use DBI;
    use DBI::Profile (dbi_profile dbi_time);
    my $t1 = dbi_time(); # floating point high-resolution time
    ... execute code you want to profile here ...
    my $t2 = dbi_time();
    dbi_profile($h, $statement, $method, $t1, $t2);

The $h parameter is the handle the extra profile sample should be associated with. The $statement parameter is the string to use where the Path specifies !Statement. If $statement is undef then $h->{Statement} will be used. Similarly $method is the string to use if the Path specifies !MethodName. There is no default value for $method.

The $h->{Profile}{Path} attribute is processed by dbi_profile() in the usual way.

The $h parameter is usually a DBI handle but it can also be a reference to a hash, in which case the dbi_profile() acts on each defined value in the hash. This is an efficient way to update multiple profiles with a single sample, and is used by the DashProfiler module.