profile.html

perl教程

    <span class="keyword">print</span> <span class="variable">$h</span><span class="operator">-&gt;</span><span class="operator">{</span><span class="string">Profile</span><span class="operator">}</span><span class="operator">-&gt;</span><span class="keyword">format</span><span class="operator">;</span>
</pre>
<p>To discard the profile data and start collecting fresh data
you can do:</p>
<pre>
    <span class="variable">$h</span><span class="operator">-&gt;</span><span class="operator">{</span><span class="string">Profile</span><span class="operator">}</span><span class="operator">-&gt;</span><span class="operator">{</span><span class="string">Data</span><span class="operator">}</span> <span class="operator">=</span> <span class="keyword">undef</span><span class="operator">;</span>
</pre>
<p>The default results format looks like this:</p>
<pre>
  DBI::Profile: 0.001015s 42.7% (5 calls) programname @ YYYY-MM-DD HH:MM:SS
  '' =&gt;
      0.000024s / 2 = 0.000012s avg (first 0.000015s, min 0.000009s, max 0.000015s)
  'SELECT mode,size,name FROM table' =&gt;
      0.000991s / 3 = 0.000330s avg (first 0.000678s, min 0.000009s, max 0.000678s)</pre>
<p>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.</p>
<p>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
calculated using the time between the first and last call to the DBI.</p>
<p>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).</p>
<p>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.</p>
<p>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:</p>
<pre>
  'SELECT mode,size,name FROM table' =&gt;
      'FETCH' =&gt;
          0.000076s
      'fetchrow_hashref' =&gt;
          0.036203s / 108 = 0.000335s avg (first 0.000490s, min 0.000152s, max 0.002786s)</pre>
<p>Here you can see the 'avg', 'first', 'min' and 'max' for the
108 calls to <code>fetchrow_hashref()</code> become rather more interesting.
Also the data for FETCH just shows a time value because it was only
called once.</p>
<p>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.</p>
<p>
</p>
<h2><a name="report_destination">Report Destination</a></h2>
<p>The default method of reporting is for the DESTROY method of the
Profile object to format the results and write them using:</p>
<pre>
    <span class="variable">DBI</span><span class="operator">-&gt;</span><span class="variable">trace_msg</span><span class="operator">(</span><span class="variable">$results</span><span class="operator">,</span> <span class="number">0</span><span class="operator">);</span>  <span class="comment"># see $ON_DESTROY_DUMP below</span>
</pre>
<p>to write them to the DBI <code>trace()</code> filehandle (which defaults to
STDERR). To direct the DBI trace filehandle to write to a file
without enabling tracing the <code>trace()</code> method can be called with a
trace level of 0. For example:</p>
<pre>
    <span class="variable">DBI</span><span class="operator">-&gt;</span><span class="variable">trace</span><span class="operator">(</span><span class="number">0</span><span class="operator">,</span> <span class="variable">$filename</span><span class="operator">);</span>
</pre>
<p>The same effect can be achieved without changing the code by
setting the <code>DBI_TRACE</code> environment variable to <code>0=filename</code>.</p>
<p>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:</p>
<pre>
  <span class="variable">$ON_DESTROY_DUMP</span> <span class="operator">=</span> <span class="keyword">sub</span><span class="variable"> </span><span class="operator">{</span> <span class="variable">DBI</span><span class="operator">-&gt;</span><span class="variable">trace_msg</span><span class="operator">(</span><span class="variable">$results</span><span class="operator">,</span> <span class="number">0</span><span class="operator">)</span> <span class="operator">};</span>
</pre>
<p>Apart from making it easy to send the dump elsewhere, it can also
be useful as a simple way to disable dumping results.</p>
<p>
</p>
<hr />
<h1><a name="child_handles">CHILD HANDLES</a></h1>
<p>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.</p>
<p>
</p>
<hr />
<h1><a name="custom_data_manipulation">CUSTOM DATA MANIPULATION</a></h1>
<p>Recall that <code>$h-</code>{Profile}-&gt;{Data}&gt; is a reference to the collected data.
Either to a 'leaf' array (when the Path is empty, i.e., DBI_PROFILE env var is 1),
or a reference to hash containing values that are either further hash
references or leaf array references.</p>
<p>Sometimes it's useful to be able to summarise some or all of the collected data.
The <code>dbi_profile_merge()</code> function can be used to merge leaf node values.</p>
<p>
</p>
<h2><a name="dbi_profile_merge">dbi_profile_merge</a></h2>
<pre>
  <span class="keyword">use</span> <span class="variable">DBI</span> <span class="string">qw(dbi_profile_merge)</span><span class="operator">;</span>
</pre>
<pre>
  <span class="variable">$time_in_dbi</span> <span class="operator">=</span> <span class="variable">dbi_profile_merge</span><span class="operator">(</span><span class="keyword">my</span> <span class="variable">$totals</span><span class="operator">=</span><span class="operator">[]</span><span class="operator">,</span> <span class="variable">@$leaves</span><span class="operator">);</span>
</pre>
<p>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:</p>
<pre>
  <span class="variable">$time_in_dbi</span> <span class="operator">=</span> <span class="variable">dbi_profile_merge</span><span class="operator">(</span>
      <span class="keyword">my</span> <span class="variable">$totals</span><span class="operator">=</span><span class="operator">[]</span><span class="operator">,</span>
      <span class="operator">[</span> <span class="number">10</span><span class="operator">,</span> <span class="number">0</span><span class="operator">.</span><span class="number">51</span><span class="operator">,</span> <span class="number">0</span><span class="operator">.</span><span class="number">11</span><span class="operator">,</span> <span class="number">0</span><span class="operator">.</span><span class="number">01</span><span class="operator">,</span> <span class="number">0</span><span class="operator">.</span><span class="number">22</span><span class="operator">,</span> <span class="number">1023110000</span><span class="operator">,</span> <span class="number">1023110010</span> <span class="operator">]</span><span class="operator">,</span>
      <span class="operator">[</span> <span class="number">15</span><span class="operator">,</span> <span class="number">0</span><span class="operator">.</span><span class="number">42</span><span class="operator">,</span> <span class="number">0</span><span class="operator">.</span><span class="number">12</span><span class="operator">,</span> <span class="number">0</span><span class="operator">.</span><span class="number">02</span><span class="operator">,</span> <span class="number">0</span><span class="operator">.</span><span class="number">23</span><span class="operator">,</span> <span class="number">1023110005</span><span class="operator">,</span> <span class="number">1023110009</span> <span class="operator">]</span><span class="operator">,</span>
  <span class="operator">);</span>
</pre>
<p>$totals will then contain</p>
<pre>
  [ 25, 0.93, 0.11, 0.01, 0.23, 1023110000, 1023110010 ]</pre>
<p>and $time_in_dbi will be 0.93;</p>
<p>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:</p>
<pre>
  <span class="keyword">my</span> <span class="variable">$time_in_dbi</span> <span class="operator">=</span> <span class="number">0</span><span class="operator">;</span>
  <span class="keyword">if</span> <span class="operator">(</span><span class="keyword">my</span> <span class="variable">$Profile</span> <span class="operator">=</span> <span class="variable">$dbh</span><span class="operator">-&gt;</span><span class="operator">{</span><span class="string">Profile</span><span class="operator">}</span><span class="operator">)</span> <span class="operator">{</span> <span class="comment"># if DBI profiling is enabled</span>
      <span class="variable">$time_in_dbi</span> <span class="operator">=</span> <span class="variable">dbi_profile_merge</span><span class="operator">(</span><span class="keyword">my</span> <span class="variable">$total</span><span class="operator">=</span><span class="operator">[]</span><span class="operator">,</span> <span class="variable">$Profile</span><span class="operator">-&gt;</span><span class="operator">{</span><span class="string">Data</span><span class="operator">}</span><span class="operator">);</span>
      <span class="variable">$Profile</span><span class="operator">-&gt;</span><span class="operator">{</span><span class="string">Data</span><span class="operator">}</span> <span class="operator">=</span> <span class="operator">{}</span><span class="operator">;</span> <span class="comment"># reset the profile data</span>
  <span class="operator">}</span>
</pre>
<p>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.</p>
<p>
</p>
<hr />
<h1><a name="custom_data_collection">CUSTOM DATA COLLECTION</a></h1>
<p>
</p>
<h2><a name="using_the_path_attribute">Using The Path Attribute</a></h2>
<pre>
  <span class="variable">XXX</span> <span class="variable">example</span> <span class="variable">to</span> <span class="variable">be</span> <span class="variable">added</span> <span class="variable">later</span> <span class="variable">using</span> <span class="variable">a</span> <span class="variable">selectall_arrayref</span> <span class="variable">call</span>
  <span class="variable">XXX</span> <span class="variable">nested</span> <span class="variable">inside</span> <span class="variable">a</span> <span class="variable">fetch</span> <span class="variable">loop</span> <span class="variable">where</span> <span class="variable">the</span> <span class="variable">first</span> <span class="variable">column</span> <span class="variable">of</span> <span class="variable">the</span>
  <span class="variable">XXX</span> <span class="variable">outer</span> <span class="variable">loop</span> <span class="variable">is</span> <span class="variable">bound</span> <span class="variable">to</span> <span class="variable">the</span> <span class="variable">profile</span> <span class="variable">Path</span> <span class="variable">using</span>
  <span class="variable">XXX</span> <span class="variable">bind_column</span><span class="operator">(</span><span class="number">1</span><span class="operator">,</span> <span class="operator">\</span><span class="variable">$</span><span class="operator">{</span> <span class="variable">$dbh</span><span class="operator">-&gt;</span><span class="operator">{</span><span class="string">Profile</span><span class="operator">}</span><span class="operator">-&gt;</span><span class="operator">{</span><span class="string">Path</span><span class="operator">}</span><span class="operator">-&gt;</span><span class="operator">[</span><span class="number">0</span><span class="operator">]</span> <span class="operator">}</span><span class="operator">)</span>
  <span class="variable">XXX</span> <span class="variable">so</span> <span class="variable">you</span> <span class="variable">end</span> <span class="variable">up</span> <span class="variable">with</span> <span class="variable">separate</span> <span class="variable">profiles</span> <span class="keyword">for</span> <span class="keyword">each</span> <span class="variable">loop</span>
  <span class="variable">XXX</span> <span class="operator">(</span><span class="variable">patches</span> <span class="variable">welcome</span> <span class="variable">to</span> <span class="variable">add</span> <span class="variable">this</span> <span class="variable">to</span> <span class="variable">the</span> <span class="variable">docs</span> <span class="operator">:)</span>
</pre>
<p>
</p>
<h2><a name="adding_your_own_samples">Adding Your Own Samples</a></h2>
<p>The <code>dbi_profile()</code> function can be used to add extra sample data
into the profile data tree. For example:</p>
<pre>
    <span class="keyword">use</span> <span class="variable">DBI</span><span class="operator">;</span>
    <span class="keyword">use</span> <span class="variable">DBI::Profile</span> <span class="operator">(</span><span class="variable">dbi_profile</span> <span class="variable">dbi_time</span><span class="operator">);</span>
</pre>
<pre>
    <span class="keyword">my</span> <span class="variable">$t1</span> <span class="operator">=</span> <span class="variable">dbi_time</span><span class="operator">();</span> <span class="comment"># floating point high-resolution time</span>
</pre>
<pre>
    ... execute code you want to profile here ...</pre>
<pre>
    <span class="keyword">my</span> <span class="variable">$t2</span> <span class="operator">=</span> <span class="variable">dbi_time</span><span class="operator">();</span>
    <span class="variable">dbi_profile</span><span class="operator">(</span><span class="variable">$h</span><span class="operator">,</span> <span class="variable">$statement</span><span class="operator">,</span> <span class="variable">$method</span><span class="operator">,</span> <span class="variable">$t1</span><span class="operator">,</span> <span class="variable">$t2</span><span class="operator">);</span>
</pre>
<p>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-&gt;{Statement} will be used. Similarly $method is the string
to use if the Path specifies !MethodName. There is no
default value for $method.</p>
<p>The $h-&gt;{Profile}{Path} attribute is processed by <code>dbi_profile()</code> in
the usual way.</p>
<p>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.</p>
<p>
</p>
<hr />
<h1><a name="subclassing">SUBCLASSING</a></h1>
<p>Alternate profile modules must subclass DBI::Profile to help ensure
they work with future versions of the DBI.</p>
<p>
</p>
<hr />
<h1><a name="caveats">CAVEATS</a></h1>
<p>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.</p>
<p>If a method throws an exception itself (not via RaiseError) then
it won't be counted in the profile.</p>
<p>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.</p>
<p>Time spent in DESTROY is added to the profile of the parent handle.</p>
<p>Time spent in DBI-&gt;*() methods is not counted. The time spent in
the driver connect method, $drh-&gt;connect(), when it's called by
DBI-&gt;connect is counted if the DBI_PROFILE environment variable is set.</p>
<p>Time spent fetching tied variables, $DBI::errstr, is counted.</p>
<p>Time spent in FETCH for $h-&gt;{Profile} is not counted, so getting the profile
data doesn't alter it.</p>
<p>DBI::PurePerl does not support profiling (though it could in theory).</p>
<p>A few platforms don't support the <code>gettimeofday()</code> high resolution
time function used by the DBI (and available via the <code>dbi_time()</code> function).
In which case you'll get integer resolution time which is mostly useless.</p>
<p>On Windows platforms the <code>dbi_time()</code> 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 general will have much more 'jitter' depending on where
within the 'current millisecond' the start and and timing was taken.</p>
<p>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!)</p>

</body>

</html>