DBI::Profile man page on HP-UX

Man page or keyword search:  
man Server   10987 pages
apropos Keyword Search (all sections)
Output format
HP-UX logo
[printable version]

DBI::Profile(3)	      User Contributed Perl Documentation      DBI::Profile(3)

       DBI::Profile - Performance profiling and benchmarking for the DBI

       The easiest way to enable DBI profiling is to set the DBI_PROFILE envi‐
       ronment variable to 2 and then run your code as usual:

	 DBI_PROFILE=2 prog.pl

       This will profile your program and then output a textual summary
       grouped by query when the program exits.	 You can also enable profiling
       by setting the Profile attribute of any DBI handle:

	 $dbh->{Profile} = 2;

       Then the summary will be printed when the handle is destroyed.

       Many other values apart from are possible - see "ENABLING A PROFILE"

       The DBI::Profile module provides a simple interface to collect and
       report performance and benchmarking data from the DBI.

       For a more elaborate interface, suitable for larger programs, see
       DBI::ProfileDumper and dbiprof.	For Apache/mod_perl applications see

       Performance data collection for the DBI is built around several con‐
       cepts which are important to understand clearly.

       Method Dispatch
	   Every method call on a DBI handle passes through a single 'dis‐
	   patch' function which manages all the common aspects of DBI method
	   calls, such as handling the RaiseError attribute.

       Data Collection
	   If profiling is enabled for a handle then the dispatch code takes a
	   high-resolution timestamp soon after it is entered. Then, after
	   calling the appropriate method and just before returning, it takes
	   another high-resolution timestamp and calls a function to record
	   the information.  That function is passed the two timestamps plus
	   the DBI handle and the name of the method that was called.  That
	   data about a single DBI method call is called a profile sample.

       Data Filtering
	   If the method call was invoked by the DBI or by a driver then the
	   call is ignored for profiling because the time spent will be
	   accounted for by the original 'outermost' call for your code.

	   For example, the calls that the selectrow_arrayref() method makes
	   to prepare() and execute() etc. are not counted individually
	   because the time spent in those methods is going to be allocated to
	   the selectrow_arrayref() method when it returns. If this was not
	   done then it would be very easy to double count time spent inside
	   the DBI.

       Data Storage Tree
	   The profile data is accumulated as 'leaves on a tree'. The 'path'
	   through the branches of the tree to a particular leaf is determined
	   dynamically for each sample.	 This is a key feature of DBI profili‐

	   For each profiled method call the DBI walks along the Path and uses
	   each value in the Path to step into and grow the Data tree.

	   For example, if the Path is

	     [ 'foo', 'bar', 'baz' ]

	   then the new profile sample data will be merged into the tree at


	   But it's not very useful to merge all the call data into one leaf
	   node (except to get an overall 'time spent inside the DBI' total).
	   It's more common to want the Path to include dynamic values such as
	   the current statement text and/or the name of the method called to
	   show what the time spent inside the DBI was for.

	   The Path can contain some 'magic cookie' values that are automati‐
	   cally replaced by corresponding dynamic values when they're used.
	   These magic cookies always start with a punctuation character.

	   For example a value of '"!MethodName"' in the Path causes the cor‐
	   responding entry in the Data to be the name of the method that was
	   called.  For example, if the Path was:

	     [ 'foo', '!MethodName', 'bar' ]

	   and the selectall_arrayref() method was called, then the profile
	   sample data for that call will be merged into the tree at:


       Profile Data
	   Profile data is stored at the 'leaves' of the tree as references to
	   an array of numeric values. For example:

	       106,		     # 0: count of samples at this node
	       0.0312958955764771,   # 1: total duration
	       0.000490069389343262, # 2: first duration
	       0.000176072120666504, # 3: shortest duration
	       0.00140702724456787,  # 4: longest duration
	       1023115819.83019,     # 5: time of first sample
	       1023115819.86576,     # 6: time of last sample

	   After the first sample, later samples always update elements 0, 1,
	   and 6, and may update 3 or 4 depending on the duration of the sam‐
	   pled call.

       Profiling is enabled for a handle by assigning to the Profile
       attribute. For example:

	 $h->{Profile} = DBI::Profile->new();

       The Profile attribute holds a blessed reference to a hash object that
       contains the profile data and attributes relating to it.

       The class the Profile object is blessed into is expected to provide at
       least a DESTROY method which will dump the profile data to the DBI
       trace file handle (STDERR by default).

       All these examples have the same effect as each other:

	 $h->{Profile} = 0;
	 $h->{Profile} = "/DBI::Profile";
	 $h->{Profile} = DBI::Profile->new();
	 $h->{Profile} = {};
	 $h->{Profile} = { Path => [] };

       Similarly, these examples have the same effect as each other:

	 $h->{Profile} = 6;
	 $h->{Profile} = "6/DBI::Profile";
	 $h->{Profile} = "!Statement:!MethodName/DBI::Profile";
	 $h->{Profile} = { Path => [ '!Statement', '!MethodName' ] };

       If a non-blessed hash reference is given then the DBI::Profile module
       is automatically "require"'d and the reference is blessed into that

       If a string is given then it is processed like this:

	   ($path, $module, $args) = split /\//, $string, 3

	   @path = split /:/, $path
	   @args = split /:/, $args

	   eval "require $module" if $module
	   $module ⎪⎪= "DBI::Profile"

	   $module->new( Path => \@Path, @args )

       So the first value is used to select the Path to be used (see below).
       The second value, if present, is used as the name of a module which
       will be loaded and it's "new" method called. If not present it defaults
       to DBI::Profile. Any other values are passed as arguments to the "new"
       method. For example: ""2/DBIx::OtherProfile/Foo:42"".

       Numbers can be used as a shorthand way to enable common Path values.
       The simplest way to explain how the values are interpreted is to show
       the code:

	   push @Path, "DBI"	       if $path_elem & 0x01;
	   push @Path, "!Statement"    if $path_elem & 0x02;
	   push @Path, "!MethodName"   if $path_elem & 0x04;
	   push @Path, "!MethodClass"  if $path_elem & 0x08;
	   push @Path, "!Caller2"      if $path_elem & 0x10;

       So "2" is the same as "!Statement" and "6" (2+4) is the same as
       "!Statement:!Method".  Those are the two most commonly used values.
       Using a negative number will reverse the path. Thus "-6" will group by
       method name then statement.

       The spliting and parsing of string values assigned to the Profile
       attribute may seem a little odd, but there's a good reason for it.
       Remember that attributes can be embedded in the Data Source Name string
       which can be passed in to a script as a parameter. For example:


       And also, if the "DBI_PROFILE" environment variable is set then The DBI
       arranges for every driver handle to share the same profile object. When
       perl exits a single profile summary will be generated that reflects (as
       nearly as practical) the total use of the DBI by the application.

       The DBI core expects the Profile attribute value to be a hash reference
       and if the following values don't exist it will create them as needed:


       A reference to a hash containing the collected profile data.


       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


       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 han‐
       dle. That can lead to a little 'fuzzyness' because, for example, calls
       to the quote() method to build a new statement will typically be asso‐
       ciated with the previous statement. In practice this isn't a signifi‐
       cant issue and the dynamic Path mechanism can be used to setup your own


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


       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' =>
	 '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 inher‐
       ited the selectrow_arrayref method provided by the DBI.

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


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


       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


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


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


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


       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 exam‐

	   [ '!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

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

       Subroutine Specifier

       A Path element that begins with '"&"' is treated as the name of a sub‐
       routine in the DBI::ProfileSubs namespace and replaced with the corre‐
       sponding code reference.

       Currently this only works when the Path is specified by the "DBI_PRO‐
       FILE" 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 informa‐

       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 'contex‐
       tual' values into your profile.

       Other Values

       Any other values are stringified and used literally.

       (References, and values that begin with punctuation characters are

       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 formated version of the profile data tree.

       If the results are being formated 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 calcu‐
       lated 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

       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' =>
	     '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 Pro‐
       file 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

	   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.

       Child handles inherit a reference to the Profile attribute value of
       their parent.  So if profiling is enabled for a database handle then by
       default the statement handles created from it all contribute to the
       same merged profile data tree.


       See "REPORTING".


	 @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

       For example, given a data tree like this:


       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 speci‐
       fied 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 a ref to an empty array.


	 @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 contatenated 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 elemets 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().

       The "format" argument is a "sprintf" format string that specifies the
       format to use for each leaf node.  It uses the explicit format parame‐
       ter 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/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

       Recall that "$h-"{Profile}->{Data}> is a reference to the collected
       data.  Either to a 'leaf' array (when the Path is empty, i.e., DBI_PRO‐
       FILE env var is 1), or a reference to hash containing values that are
       either further hash references or leaf array references.

       Sometimes it's useful to be able to summarise some or all of the col‐
       lected data.  The dbi_profile_merge_nodes() function can be used to
       merge leaf node values.


	 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 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 asso‐
       ciated 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 speci‐
       fies !MethodName. There is no default value for $method.

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

       It is recommended that you keep these extra data samples separate from
       the DBI profile data samples by using values for $statement and $method
       that are distinct from any that are likely to appear in the profile
       data normally.

       Alternate profile modules must subclass DBI::Profile to help ensure
       they work with future versions of the DBI.

       Applications which generate many different statement strings (typically
       because they don't use placeholders) and profile with !Statement in the
       Path (the default) will consume memory in the Profile Data structure
       for each statement. Use a code ref in the Path to return an edited
       (simplified) form of the statement.

       If a method throws an exception itself (not via RaiseError) then it
       won't be counted in the profile.

       If a HandleError subroutine throws an exception (rather than returning
       0 and letting RaiseError do it) then the method call won't be counted
       in the profile.

       Time spent in DESTROY is added to the profile of the parent handle.

       Time spent in DBI->*() methods is not counted. The time spent in the
       driver connect method, $drh->connect(), when it's called by DBI->con‐
       nect is counted if the DBI_PROFILE environment variable is set.

       Time spent fetching tied variables, $DBI::errstr, is counted.

       Time spent in FETCH for $h->{Profile} is not counted, so getting the
       profile data doesn't alter it.

       DBI::PurePerl does not support profiling (though it could in theory).

       A few platforms don't support the gettimeofday() high resolution time
       function used by the DBI (and available via the dbi_time() function).
       In which case you'll get integer resolution time which is mostly use‐

       On Windows platforms the dbi_time() function is limited to millisecond
       resolution. Which isn't sufficiently fine for our needs, but still much
       better than integer resolution. This limited resolution means that fast
       method calls will often register as taking 0 time. And timings in gen‐
       eral will have much more 'jitter' depending on where within the 'cur‐
       rent millisecond' the start and and timing was taken.

       This documentation could be more clear. Probably needs to be reordered
       to start with several examples and build from there.  Trying to explain
       the concepts first seems painful and to lead to just as many forward
       references.  (Patches welcome!)

perl v5.8.8			  2007-05-13		       DBI::Profile(3)

List of man pages available for HP-UX

Copyright (c) for man pages and the logo by the respective OS vendor.

For those who want to learn more, the polarhome community provides shell access and support.

[legal] [privacy] [GNU] [policy] [cookies] [netiquette] [sponsors] [FAQ]
Polarhome, production since 1999.
Member of Polarhome portal.
Based on Fawad Halim's script.
Vote for polarhome
Free Shell Accounts :: the biggest list on the net