{ "mode": "perldoc", "parameter": "DBI::Profile", "section": "", "url": "https://www.chedong.com/phpMan.php/perldoc/DBI%3A%3AProfile/json", "generated": "2026-06-13T21:28:56Z", "synopsis": "The easiest way to enable DBI profiling is to set the DBIPROFILE environment variable to 2 and\nthen run your code as usual:\nDBIPROFILE=2 prog.pl\nThis will profile your program and then output a textual summary grouped by query when the\nprogram exits. You can also enable profiling by setting the Profile attribute of any DBI handle:\n$dbh->{Profile} = 2;\nThen the summary will be printed when the handle is destroyed.\nMany other values apart from are possible - see \"ENABLING A PROFILE\" below.", "sections": { "NAME": { "content": "DBI::Profile - Performance profiling and benchmarking for the DBI\n", "subsections": [] }, "SYNOPSIS": { "content": "The easiest way to enable DBI profiling is to set the DBIPROFILE environment variable to 2 and\nthen run your code as usual:\n\nDBIPROFILE=2 prog.pl\n\nThis will profile your program and then output a textual summary grouped by query when the\nprogram exits. You can also enable profiling by setting the Profile attribute of any DBI handle:\n\n$dbh->{Profile} = 2;\n\nThen the summary will be printed when the handle is destroyed.\n\nMany other values apart from are possible - see \"ENABLING A PROFILE\" below.\n", "subsections": [] }, "DESCRIPTION": { "content": "The DBI::Profile module provides a simple interface to collect and report performance and\nbenchmarking data from the DBI.\n\nFor a more elaborate interface, suitable for larger programs, see DBI::ProfileDumper and\ndbiprof. For Apache/modperl applications see DBI::ProfileDumper::Apache.\n", "subsections": [] }, "OVERVIEW": { "content": "Performance data collection for the DBI is built around several concepts which are important to\nunderstand clearly.\n\nMethod Dispatch\nEvery method call on a DBI handle passes through a single 'dispatch' function which manages\nall the common aspects of DBI method calls, such as handling the RaiseError attribute.\n\nData Collection\nIf profiling is enabled for a handle then the dispatch code takes a high-resolution\ntimestamp soon after it is entered. Then, after calling the appropriate method and just\nbefore returning, it takes another high-resolution timestamp and calls a function to record\nthe information. That function is passed the two timestamps plus the DBI handle and the name\nof the method that was called. That data about a single DBI method call is called a *profile\nsample*.\n\nData Filtering\nIf the method call was invoked by the DBI or by a driver then the call is ignored for\nprofiling because the time spent will be accounted for by the original 'outermost' call for\nyour code.\n\nFor example, the calls that the selectrowarrayref() method makes to prepare() and execute()\netc. are not counted individually because the time spent in those methods is going to be\nallocated to the selectrowarrayref() method when it returns. If this was not done then it\nwould be very easy to double count time spent inside the DBI.\n\nData Storage Tree\nThe profile data is accumulated as 'leaves on a tree'. The 'path' through the branches of\nthe tree to a particular leaf is determined dynamically for each sample. This is a key\nfeature of DBI profiling.\n\nFor each profiled method call the DBI walks along the Path and uses each value in the Path\nto step into and grow the Data tree.\n\nFor example, if the Path is\n\n[ 'foo', 'bar', 'baz' ]\n\nthen the new profile sample data will be *merged* into the tree at\n\n$h->{Profile}->{Data}->{foo}->{bar}->{baz}\n\nBut it's not very useful to merge all the call data into one leaf node (except to get an\noverall 'time spent inside the DBI' total). It's more common to want the Path to include\ndynamic values such as the current statement text and/or the name of the method called to\nshow what the time spent inside the DBI was for.\n\nThe Path can contain some 'magic cookie' values that are automatically replaced by\ncorresponding dynamic values when they're used. These magic cookies always start with a\npunctuation character.\n\nFor example a value of '\"!MethodName\"' in the Path causes the corresponding entry in the\nData to be the name of the method that was called. For example, if the Path was:\n\n[ 'foo', '!MethodName', 'bar' ]\n\nand the selectallarrayref() method was called, then the profile sample data for that call\nwill be merged into the tree at:\n\n$h->{Profile}->{Data}->{foo}->{selectallarrayref}->{bar}\n\nProfile Data\nProfile data is stored at the 'leaves' of the tree as references to an array of numeric\nvalues. For example:\n\n[\n106, # 0: count of samples at this node\n0.0312958955764771, # 1: total duration\n0.000490069389343262, # 2: first duration\n0.000176072120666504, # 3: shortest duration\n0.00140702724456787, # 4: longest duration\n1023115819.83019, # 5: time of first sample\n1023115819.86576, # 6: time of last sample\n]\n\nAfter the first sample, later samples always update elements 0, 1, and 6, and may update 3\nor 4 depending on the duration of the sampled call.\n", "subsections": [] }, "ENABLING A PROFILE": { "content": "Profiling is enabled for a handle by assigning to the Profile attribute. For example:\n\n$h->{Profile} = DBI::Profile->new();\n\nThe Profile attribute holds a blessed reference to a hash object that contains the profile data\nand attributes relating to it.\n\nThe class the Profile object is blessed into is expected to provide at least a DESTROY method\nwhich will dump the profile data to the DBI trace file handle (STDERR by default).\n\nAll these examples have the same effect as each other:\n\n$h->{Profile} = 0;\n$h->{Profile} = \"/DBI::Profile\";\n$h->{Profile} = DBI::Profile->new();\n$h->{Profile} = {};\n$h->{Profile} = { Path => [] };\n\nSimilarly, these examples have the same effect as each other:\n\n$h->{Profile} = 6;\n$h->{Profile} = \"6/DBI::Profile\";\n$h->{Profile} = \"!Statement:!MethodName/DBI::Profile\";\n$h->{Profile} = { Path => [ '!Statement', '!MethodName' ] };\n\nIf a non-blessed hash reference is given then the DBI::Profile module is automatically\n\"require\"'d and the reference is blessed into that class.\n\nIf a string is given then it is processed like this:\n\n($path, $module, $args) = split /\\//, $string, 3\n\n@path = split /:/, $path\n@args = split /:/, $args\n\neval \"require $module\" if $module\n$module ||= \"DBI::Profile\"\n\n$module->new( Path => \\@Path, @args )\n\nSo the first value is used to select the Path to be used (see below). The second value, if\npresent, is used as the name of a module which will be loaded and it's \"new\" method called. If\nnot present it defaults to DBI::Profile. Any other values are passed as arguments to the \"new\"\nmethod. For example: \"\"2/DBIx::OtherProfile/Foo:42\"\".\n\nNumbers can be used as a shorthand way to enable common Path values. The simplest way to explain\nhow the values are interpreted is to show the code:\n\npush @Path, \"DBI\" if $pathelem & 0x01;\npush @Path, \"!Statement\" if $pathelem & 0x02;\npush @Path, \"!MethodName\" if $pathelem & 0x04;\npush @Path, \"!MethodClass\" if $pathelem & 0x08;\npush @Path, \"!Caller2\" if $pathelem & 0x10;\n\nSo \"2\" is the same as \"!Statement\" and \"6\" (2+4) is the same as \"!Statement:!Method\". Those are\nthe two most commonly used values. Using a negative number will reverse the path. Thus \"-6\" will\ngroup by method name then statement.\n\nThe splitting and parsing of string values assigned to the Profile attribute may seem a little\nodd, but there's a good reason for it. Remember that attributes can be embedded in the Data\nSource Name string which can be passed in to a script as a parameter. For example:\n\ndbi:DriverName(Profile=>2):dbname\ndbi:DriverName(Profile=>{Username}:!Statement/MyProfiler/Foo:42):dbname\n\nAnd also, if the \"DBIPROFILE\" environment variable is set then The DBI arranges for every\ndriver handle to share the same profile object. When perl exits a single profile summary will be\ngenerated that reflects (as nearly as practical) the total use of the DBI by the application.\n", "subsections": [] }, "THE PROFILE OBJECT": { "content": "The DBI core expects the Profile attribute value to be a hash reference and if the following\nvalues don't exist it will create them as needed:\n", "subsections": [ { "name": "Data", "content": "A reference to a hash containing the collected profile data.\n" }, { "name": "Path", "content": "The Path value is a reference to an array. Each element controls the value to use at the\ncorresponding level of the profile Data tree.\n\nIf the value of Path is anything other than an array reference, it is treated as if it was:\n\n[ '!Statement' ]\n\nThe elements of Path array can be one of the following types:\n\nSpecial Constant\n!Statement\n\nUse the current Statement text. Typically that's the value of the Statement attribute for the\nhandle the method was called with. Some methods, like commit() and rollback(), are unrelated to\na particular statement. For those methods !Statement records an empty string.\n\nFor statement handles this is always simply the string that was given to prepare() when the\nhandle was created. For database handles this is the statement that was last prepared or\nexecuted on that database handle. That can lead to a little 'fuzzyness' because, for example,\ncalls to the quote() method to build a new statement will typically be associated with the\nprevious statement. In practice this isn't a significant issue and the dynamic Path mechanism\ncan be used to setup your own rules.\n\n!MethodName\n\nUse the name of the DBI method that the profile sample relates to.\n\n!MethodClass\n\nUse the fully qualified name of the DBI method, including the package, that the profile sample\nrelates to. This shows you where the method was implemented. For example:\n\n'DBD::::db::selectrowarrayref' =>\n0.022902s\n'DBD::mysql::db::selectrowarrayref' =>\n2.244521s / 99 = 0.022445s avg (first 0.022813s, min 0.022051s, max 0.028932s)\n\nThe \"DBD::::db::selectrowarrayref\" shows that the driver has inherited the selectrowarrayref\nmethod provided by the DBI.\n\nBut you'll note that there is only one call to DBD::::db::selectrowarrayref but another 99 to\nDBD::mysql::db::selectrowarrayref. Currently the first call doesn't record the true location.\nThat may change.\n\n!Caller\n\nUse a string showing the filename and line number of the code calling the method.\n\n!Caller2\n\nUse a string showing the filename and line number of the code calling the method, as for\n!Caller, but also include filename and line number of the code that called that. Calls from\nDBI:: and DBD:: packages are skipped.\n\n!File\n\nSame as !Caller above except that only the filename is included, not the line number.\n\n!File2\n\nSame as !Caller2 above except that only the filenames are included, not the line number.\n\n!Time\n\nUse the current value of time(). Rarely used. See the more useful \"!Time~N\" below.\n\n!Time~N\n\nWhere \"N\" is an integer. Use the current value of time() but with reduced precision. The value\nused is determined in this way:\n\nint( time() / N ) * N\n\nThis is a useful way to segregate a profile into time slots. For example:\n\n[ '!Time~60', '!Statement' ]\n\nCode Reference\nThe subroutine is passed the handle it was called on and the DBI method name. The current\nStatement is in $. The statement string should not be modified, so most subs start with \"local\n$ = $;\".\n\nThe list of values it returns is used at that point in the Profile Path. Any undefined values\nare treated as the string \"\"undef\"\".\n\nThe sub can 'veto' (reject) a profile sample by including a reference to undef (\"\\undef\") in the\nreturned list. That can be useful when you want to only profile statements that match a certain\npattern, or only profile certain methods.\n\nSubroutine Specifier\nA Path element that begins with '\"&\"' is treated as the name of a subroutine in the\nDBI::ProfileSubs namespace and replaced with the corresponding code reference.\n\nCurrently this only works when the Path is specified by the \"DBIPROFILE\" environment variable.\n\nAlso, currently, the only subroutine in the DBI::ProfileSubs namespace is '&normstdn3'. That's\na very handy subroutine when profiling code that doesn't use placeholders. See DBI::ProfileSubs\nfor more information.\n\nAttribute Specifier\nA string enclosed in braces, such as '\"{Username}\"', specifies that the current value of the\ncorresponding database handle attribute should be used at that point in the Path.\n\nReference to a Scalar\nSpecifies that the current value of the referenced scalar be used at that point in the Path.\nThis provides an efficient way to get 'contextual' values into your profile.\n\nOther Values\nAny other values are stringified and used literally.\n\n(References, and values that begin with punctuation characters are reserved.)\n" } ] }, "REPORTING": { "content": "", "subsections": [ { "name": "Report Format", "content": "The current accumulated profile data can be formatted and output using\n\nprint $h->{Profile}->format;\n\nTo discard the profile data and start collecting fresh data you can do:\n\n$h->{Profile}->{Data} = undef;\n\nThe default results format looks like this:\n\nDBI::Profile: 0.001015s 42.7% (5 calls) programname @ YYYY-MM-DD HH:MM:SS\n'' =>\n0.000024s / 2 = 0.000012s avg (first 0.000015s, min 0.000009s, max 0.000015s)\n'SELECT mode,size,name FROM table' =>\n0.000991s / 3 = 0.000330s avg (first 0.000678s, min 0.000009s, max 0.000678s)\n\nWhich shows the total time spent inside the DBI, with a count of the total number of method\ncalls and the name of the script being run, then a formatted version of the profile data tree.\n\nIf the results are being formatted when the perl process is exiting (which is usually the case\nwhen the DBIPROFILE environment variable is used) then the percentage of time the process spent\ninside the DBI is also shown. If the process is not exiting then the percentage is calculated\nusing the time between the first and last call to the DBI.\n\nIn the example above the paths in the tree are only one level deep and use the Statement text as\nthe value (that's the default behaviour).\n\nThe merged profile data at the 'leaves' of the tree are presented as total time spent, count,\naverage time spent (which is simply total time divided by the count), then the time spent on the\nfirst call, the time spent on the fastest call, and finally the time spent on the slowest call.\n\nThe 'avg', 'first', 'min' and 'max' times are not particularly useful when the profile data path\nonly contains the statement text. Here's an extract of a more detailed example using both\nstatement text and method name in the path:\n\n'SELECT mode,size,name FROM table' =>\n'FETCH' =>\n0.000076s\n'fetchrowhashref' =>\n0.036203s / 108 = 0.000335s avg (first 0.000490s, min 0.000152s, max 0.002786s)\n\nHere you can see the 'avg', 'first', 'min' and 'max' for the 108 calls to fetchrowhashref()\nbecome rather more interesting. Also the data for FETCH just shows a time value because it was\nonly called once.\n\nCurrently the profile data is output sorted by branch names. That may change in a later version\nso the leaf nodes are sorted by total time per leaf node.\n" }, { "name": "Report Destination", "content": "The default method of reporting is for the DESTROY method of the Profile object to format the\nresults and write them using:\n\nDBI->tracemsg($results, 0); # see $ONDESTROYDUMP below\n\nto write them to the DBI trace() filehandle (which defaults to STDERR). To direct the DBI trace\nfilehandle to write to a file without enabling tracing the trace() method can be called with a\ntrace level of 0. For example:\n\nDBI->trace(0, $filename);\n\nThe same effect can be achieved without changing the code by setting the \"DBITRACE\" environment\nvariable to \"0=filename\".\n\nThe $DBI::Profile::ONDESTROYDUMP variable holds a code ref that's called to perform the output\nof the formatted results. The default value is:\n\n$ONDESTROYDUMP = sub { DBI->tracemsg($results, 0) };\n\nApart from making it easy to send the dump elsewhere, it can also be useful as a simple way to\ndisable dumping results.\n" } ] }, "CHILD HANDLES": { "content": "Child handles inherit a reference to the Profile attribute value of their parent. So if\nprofiling is enabled for a database handle then by default the statement handles created from it\nall contribute to the same merged profile data tree.\n", "subsections": [] }, "PROFILE OBJECT METHODS": { "content": "format\nSee \"REPORTING\".\n\nasnodepathlist\n@ary = $dbh->{Profile}->asnodepathlist();\n@ary = $dbh->{Profile}->asnodepathlist($node, $path);\n\nReturns the collected data ($dbh->{Profile}{Data}) restructured into a list of array refs, one\nfor each leaf node in the Data tree. This 'flat' structure is often much simpler for\napplications to work with.\n\nThe first element of each array ref is a reference to the leaf node. The remaining elements are\nthe 'path' through the data tree to that node.\n\nFor example, given a data tree like this:\n\n{key1a}{key2a}[node1]\n{key1a}{key2b}[node2]\n{key1b}{key2a}{key3a}[node3]\n\nThe asnodepathlist() method will return this list:\n\n[ [node1], 'key1a', 'key2a' ]\n[ [node2], 'key1a', 'key2b' ]\n[ [node3], 'key1b', 'key2a', 'key3a' ]\n\nThe nodes are ordered by key, depth-first.\n\nThe $node argument can be used to focus on a sub-tree. If not specified it defaults to\n$dbh->{Profile}{Data}.\n\nThe $path argument can be used to specify a list of path elements that will be added to each\nelement of the returned list. If not specified it defaults to a ref to an empty array.\n\nastext\n@txt = $dbh->{Profile}->astext();\n$txt = $dbh->{Profile}->astext({\nnode => undef,\npath => [],\nseparator => \" > \",\nformat => '%1$s: %11$fs / %10$d = %2$fs avg (first %12$fs, min %13$fs, max %14$fs)'.\"\\n\";\nsortsub => sub { ... },\n);\n\nReturns the collected data ($dbh->{Profile}{Data}) reformatted into a list of formatted strings.\nIn scalar context the list is returned as a single concatenated string.\n\nA hashref can be used to pass in arguments, the default values are shown in the example above.\n\nThe \"node\" and arguments are passed to asnodepathlist().\n\nThe \"separator\" argument is used to join the elements of the path for each leaf node.\n\nThe \"sortsub\" argument is used to pass in a ref to a sub that will order the list. The\nsubroutine will be passed a reference to the array returned by asnodepathlist() and should\nsort the contents of the array in place. The return value from the sub is ignored. For example,\nto sort the nodes by the second level key you could use:\n\nsortsub => sub { my $ary=shift; @$ary = sort { $a->[2] cmp $b->[2] } @$ary }\n\nThe \"format\" argument is a \"sprintf\" format string that specifies the format to use for each\nleaf node. It uses the explicit format parameter index mechanism to specify which of the\narguments should appear where in the string. The arguments to sprintf are:\n\n1: path to node, joined with the separator\n2: average duration (total duration/count)\n(3 thru 9 are currently unused)\n10: count\n11: total duration\n12: first duration\n13: smallest duration\n14: largest duration\n15: time of first call\n16: time of first call\n", "subsections": [] }, "CUSTOM DATA MANIPULATION": { "content": "Recall that \"$h->{Profile}->{Data}\" is a reference to the collected data. Either to a 'leaf'\narray (when the Path is empty, i.e., DBIPROFILE env var is 1), or a reference to hash\ncontaining values that are either further hash references or leaf array references.\n\nSometimes it's useful to be able to summarise some or all of the collected data. The", "subsections": [ { "name": "dbi_profile_merge_nodes", "content": "dbiprofilemergenodes\nuse DBI qw(dbiprofilemergenodes);\n\n$timeindbi = dbiprofilemergenodes(my $totals=[], @$leaves);\n\nMerges profile data node. Given a reference to a destination array, and zero or more references\nto profile data, merges the profile data into the destination array. For example:\n\n$timeindbi = dbiprofilemergenodes(\nmy $totals=[],\n[ 10, 0.51, 0.11, 0.01, 0.22, 1023110000, 1023110010 ],\n[ 15, 0.42, 0.12, 0.02, 0.23, 1023110005, 1023110009 ],\n);\n\n$totals will then contain\n\n[ 25, 0.93, 0.11, 0.01, 0.23, 1023110000, 1023110010 ]\n\nand $timeindbi will be 0.93;\n\nThe second argument need not be just leaf nodes. If given a reference to a hash then the hash is\nrecursively searched for leaf nodes and all those found are merged.\n\nFor example, to get the time spent 'inside' the DBI during an http request, your logging code\nrun at the end of the request (i.e. modperl LogHandler) could use:\n\nmy $timeindbi = 0;\nif (my $Profile = $dbh->{Profile}) { # if DBI profiling is enabled\n$timeindbi = dbiprofilemergenodes(my $total=[], $Profile->{Data});\n$Profile->{Data} = {}; # reset the profile data\n}\n\nIf profiling has been enabled then $timeindbi will hold the time spent inside the DBI for that\nhandle (and any other handles that share the same profile data) since the last request.\n\nPrior to DBI 1.56 the dbiprofilemergenodes() function was called dbiprofilemerge(). That\nname still exists as an alias.\n" } ] }, "CUSTOM DATA COLLECTION": { "content": "", "subsections": [ { "name": "Using The Path Attribute", "content": "XXX example to be added later using a selectallarrayref call\nXXX nested inside a fetch loop where the first column of the\nXXX outer loop is bound to the profile Path using\nXXX bindcolumn(1, \\${ $dbh->{Profile}->{Path}->[0] })\nXXX so you end up with separate profiles for each loop\nXXX (patches welcome to add this to the docs :)\n" }, { "name": "Adding Your Own Samples", "content": "The dbiprofile() function can be used to add extra sample data into the profile data tree. For\nexample:\n\nuse DBI;\nuse DBI::Profile (dbiprofile dbitime);\n\nmy $t1 = dbitime(); # floating point high-resolution time\n\n... execute code you want to profile here ...\n\nmy $t2 = dbitime();\ndbiprofile($h, $statement, $method, $t1, $t2);\n\nThe $h parameter is the handle the extra profile sample should be associated with. The\n$statement parameter is the string to use where the Path specifies !Statement. If $statement is\nundef then $h->{Statement} will be used. Similarly $method is the string to use if the Path\nspecifies !MethodName. There is no default value for $method.\n\nThe $h->{Profile}{Path} attribute is processed by dbiprofile() in the usual way.\n\nThe $h parameter is usually a DBI handle but it can also be a reference to a hash, in which case\nthe dbiprofile() acts on each defined value in the hash. This is an efficient way to update\nmultiple profiles with a single sample, and is used by the DashProfiler module.\n" } ] }, "SUBCLASSING": { "content": "Alternate profile modules must subclass DBI::Profile to help ensure they work with future\nversions of the DBI.\n", "subsections": [] }, "CAVEATS": { "content": "Applications which generate many different statement strings (typically because they don't use\nplaceholders) and profile with !Statement in the Path (the default) will consume memory in the\nProfile Data structure for each statement. Use a code ref in the Path to return an edited\n(simplified) form of the statement.\n\nIf a method throws an exception itself (not via RaiseError) then it won't be counted in the\nprofile.\n\nIf a HandleError subroutine throws an exception (rather than returning 0 and letting RaiseError\ndo it) then the method call won't be counted in the profile.\n\nTime spent in DESTROY is added to the profile of the parent handle.\n\nTime spent in DBI->*() methods is not counted. The time spent in the driver connect method,\n$drh->connect(), when it's called by DBI->connect is counted if the DBIPROFILE environment\nvariable is set.\n\nTime spent fetching tied variables, $DBI::errstr, is counted.\n\nTime spent in FETCH for $h->{Profile} is not counted, so getting the profile data doesn't alter\nit.\n\nDBI::PurePerl does not support profiling (though it could in theory).\n\nFor asynchronous queries, time spent while the query is running on the backend is not counted.\n\nA few platforms don't support the gettimeofday() high resolution time function used by the DBI\n(and available via the dbitime() function). In which case you'll get integer resolution time\nwhich is mostly useless.\n\nOn Windows platforms the dbitime() function is limited to millisecond resolution. Which isn't\nsufficiently fine for our needs, but still much better than integer resolution. This limited\nresolution means that fast method calls will often register as taking 0 time. And timings in\ngeneral will have much more 'jitter' depending on where within the 'current millisecond' the\nstart and end timing was taken.\n\nThis documentation could be more clear. Probably needs to be reordered to start with several\nexamples and build from there. Trying to explain the concepts first seems painful and to lead to\njust as many forward references. (Patches welcome!)\n", "subsections": [] } }, "summary": "DBI::Profile - Performance profiling and benchmarking for the DBI", "flags": [], "examples": [], "see_also": [] }