📄 ch20_06.htm
字号:
<html><head><title>The Perl Profiler (Programming Perl)</title><!-- STYLESHEET --><link rel="stylesheet" type="text/css" href="../style/style1.css"><!-- METADATA --><!--Dublin Core Metadata--><meta name="DC.Creator" content=""><meta name="DC.Date" content=""><meta name="DC.Format" content="text/xml" scheme="MIME"><meta name="DC.Generator" content="XSLT stylesheet, xt by James Clark"><meta name="DC.Identifier" content=""><meta name="DC.Language" content="en-US"><meta name="DC.Publisher" content="O'Reilly & Associates, Inc."><meta name="DC.Source" content="" scheme="ISBN"><meta name="DC.Subject.Keyword" content=""><meta name="DC.Title" content="The Perl Profiler"><meta name="DC.Type" content="Text.Monograph"></head><body><!-- START OF BODY --><!-- TOP BANNER --><img src="gifs/smbanner.gif" usemap="#banner-map" border="0" alt="Book Home"><map name="banner-map"><AREA SHAPE="RECT" COORDS="0,0,466,71" HREF="index.htm" ALT="Programming Perl"><AREA SHAPE="RECT" COORDS="467,0,514,18" HREF="jobjects/fsearch.htm" ALT="Search this book"></map><!-- TOP NAV BAR --><div class="navbar"><table width="515" border="0"><tr><td align="left" valign="top" width="172"><a href="ch20_05.htm"><img src="../gifs/txtpreva.gif" alt="Previous" border="0"></a></td><td align="center" valign="top" width="171"><a href="ch20_01.htm">Chapter 20: The Perl Debugger</a></td><td align="right" valign="top" width="172"><a href="ch21_01.htm"><img src="../gifs/txtnexta.gif" alt="Next" border="0"></a></td></tr></table></div><hr width="515" align="left"><!-- SECTION BODY --><h2 class="sect1">20.6. The Perl Profiler</h2><p><a name="INDEX-3649"></a><a name="INDEX-3650"></a><a name="INDEX-3651"></a><a name="INDEX-3652"></a><a name="INDEX-3653"></a><a name="INDEX-3654"></a><a name="INDEX-3655"></a><a name="INDEX-3656"></a>Do you want to make your program faster? Well, of course you do. Butfirst you should stop and ask yourself, "Do I really need to spend timemaking this program faster?" Recreational optimization can befun,<a href="#FOOTNOTE-2">[2]</a> but normally there are better uses foryour time. Sometimes you just need to plan ahead and start the programwhen you're going on a coffee break. (Or use it as an excuse forone.) But if your program absolutely must run faster, you should beginby profiling it. A profiler can tell you which parts of your programtake the most time to execute, so you won't waste time optimizing asubroutine that has an insignificant effect on the overall executiontime.</p><blockquote class="footnote"><a name="FOOTNOTE-2"></a><p>[2] Or so says Nathan Torkington, who contributed thissection of the book.</p></blockquote><p>Perl comes with a profiler, the <tt class="literal">Devel::DProf</tt> module. You can use it toprofile the Perl program in <em class="emphasis">mycode.pl</em> by typing:<blockquote><pre class="programlisting">perl -d:DProf mycode.pl</pre></blockquote><a name="INDEX-3657"></a>Even though we've called it a profiler--since that's what it does--themechanism <tt class="literal">DProf</tt> employs is the very same one we discussed earlierin this chapter. <tt class="literal">DProf</tt> is just a debugger that records the timePerl entered and left each subroutine.</p><p><a name="INDEX-3658"></a>When your profiled script terminates, <tt class="literal">DProf</tt> will dump the timinginformation to a file called <em class="emphasis">tmon.out</em>. The <em class="emphasis">dprofpp</em> programthat came with Perl knows how to analyze <em class="emphasis">tmon.out</em> and produce a report. Youmay also use <em class="emphasis">dprofpp</em> as a frontend for the whole process with the<span class="option">-p</span> switch (see described later).</p><p>Given this program:<blockquote><pre class="programlisting">outer();sub outer { for (my $i=0; $i < 100; $i++) { inner() }}sub inner { my $total = 0; for (my $i=0; $i < 1000; $i++) { $total += $i }}inner();</pre></blockquote>the output of <em class="emphasis">dprofpp</em> is:<blockquote><pre class="programlisting">Total Elapsed Time = 0.537654 Seconds User+System Time = 0.317552 SecondsExclusive Times%Time ExclSec CumulS #Calls sec/call Csec/c Name 85.0 0.270 0.269 101 0.0027 0.0027 main::inner 2.83 0.009 0.279 1 0.0094 0.2788 main::outer</pre></blockquote>Note that the percentage numbers don't add up to 100. In fact, in thiscase, they're pretty far off, which should tip you off that you need torun the program longer. As a general rule, the more profiling data youcan collect, the better your statistical sample. If we increase theouter loop to run 1000 times instead of 100 times, we'll get moreaccurate results:<blockquote><pre class="programlisting">Total Elapsed Time = 2.875946 Seconds User+System Time = 2.855946 SecondsExclusive Times%Time ExclSec CumulS #Calls sec/call Csec/c Name 99.3 2.838 2.834 1001 0.0028 0.0028 main::inner 0.14 0.004 2.828 1 0.0040 2.8280 main::outer</pre></blockquote>The first line reports how long the program took to run, from start tofinish. The second line displays the total of two different numbers:the time spent executing your code ("user") and the time spent in theoperating system executing system calls made by your code ("system").(We'll have to forgive a bit of false precision in these numbers--thecomputer's clock almost certainly does not tick every millionth of asecond. It might tick every hundredth of a second if you're lucky.)</p><p>The "user+system" times can be changed with command-line options to<em class="emphasis">dprofpp</em>. <span class="option">-r</span> displays elapsed time, <span class="option">-s</span> displays systemtime only, and <span class="option">-u</span> displays user time only.</p><p>The rest of the report is a breakdown of the time spent in eachsubroutine. The "Exclusive Times" line indicates that when subroutine<tt class="literal">outer</tt> called subroutine <tt class="literal">inner</tt>, the time spent in <tt class="literal">inner</tt> didn'tcount towards <tt class="literal">outer</tt>'s time. To change this, causing <tt class="literal">inner</tt>'s timeto be counted towards <tt class="literal">outer</tt>'s, give the <span class="option">-I</span> option to <em class="emphasis">dprofpp</em>.</p><p>For each subroutine, the following is reported: <tt class="literal">%Time</tt>, the percentage of timespent in this subroutine call; <tt class="literal">ExclSec</tt>, the time in seconds spentin this subroutine not including those subroutines called from it;<tt class="literal">CumulS</tt>, the time in seconds spent in this subroutine and thosecalled from it; <tt class="literal">#Calls</tt>, the number of calls to the subroutine;<tt class="literal">sec/call</tt>, the average time in seconds of each call to thesubroutine not including those called from it; <tt class="literal">Csec/c</tt>, theaverage time in seconds of each call to the subroutine and thosecalled from it.</p><p>Of those, the most useful figure is <tt class="literal">%Time</tt>, which will tell you whereyour time goes. In our case, the <tt class="literal">inner</tt> subroutine takes the mosttime, so we should try to optimize that subroutine, or find analgorithm that will call it less. <tt class="literal">:-)</tt></p><p>Options to <em class="emphasis">dprofpp</em> provide access to other information or varythe way the times are calculated. You can also make <em class="emphasis">dprofpp</em> runthe script for you in the first place, so you don't have to rememberthe <span class="option">-d:DProf</span> switch:</p><dl><dt><b><span class="option">-p</span> <em class="replaceable">SCRIPT</em></b></dt><dd><p>Tells <em class="emphasis">dprofpp</em> that it should profile the given <em class="replaceable">SCRIPT</em> andthen interpret its profile data. See also <span class="option">-Q</span>.</p></dd><dt><b><span class="option">-Q</span></b></dt><dd><p>Used with <span class="option">-p</span> to tell <em class="emphasis">dprofpp</em> to quit after profiling the script, withoutinterpreting the data.</p></dd><dt><b><span class="option">-a</span></b></dt><dd><p>Sort output alphabetically by subroutine name rather than bydecreasing percentage of time.</p></dd><dt><b><span class="option">-R</span></b></dt><dd><p>Count anonymous subroutines defined in the same package separately.The default behavior is to count all anonymous subroutines asone, named <tt class="literal">main::__ANON__</tt>.</p></dd><dt><b><span class="option">-I</span></b></dt><dd><p>Display all subroutine times inclusive of child subroutine times.</p></dd><dt><b><span class="option">-l</span></b></dt><dd><p>Sort by number of calls to the subroutines. This may help identifycandidates for inlining.</p></dd><dt><b><span class="option">-O</span> <em class="replaceable">COUNT</em></b></dt><dd><p>Show only the top <em class="replaceable">COUNT</em> subroutines. The default is 15.</p></dd><dt><b><span class="option">-q</span></b></dt><dd><p>Do not display column headers.</p></dd><dt><b><span class="option">-T</span></b></dt><dd><p>Display the subroutine call tree to standard output. Subroutine statistics arenot displayed.</p></dd><dt><b><span class="option">-t</span></b></dt><dd><p>Display the subroutine call tree to standard output. Subroutinestatistics are not displayed. A function called multiple (consecutive)times at the same calling level is displayed once, with a repeatcount.</p></dd><dt><b><span class="option">-S</span></b></dt><dd><p>Produce output structured by the way your subroutines call oneanother:<blockquote><pre class="programlisting">main::inner x 1 0.008smain::outer x 1 0.467s = (0.000 + 0.468)s main::inner x 100 0.468s</pre></blockquote>Read this as follows: the top level of your program called <tt class="literal">inner</tt> once, andit ran for 0.008s elapsed time, and the top level called <tt class="literal">outer</tt> onceand it ran for 0.467s inclusively (0s in <tt class="literal">outer</tt> itself, 0.468s in thesubroutines called from <tt class="literal">outer</tt>) calling <tt class="literal">inner</tt> 100 times (which ranfor 0.468s). Whew, got that?</p><p>Branches at the same level (for example, <tt class="literal">inner</tt> called once and <tt class="literal">outer</tt>called once) are sorted by inclusive time.</p></dd><dt><b><span class="option">-U</span></b></dt><dd><p>Do not sort. Display in the order found in the raw profile.</p></dd><dt><b><span class="option">-v</span></b></dt><dd><p>Sort by average time spent in subroutines during each call. This mayhelp identify candidates for hand optimization by inlining subroutine bodies.</p></dd><dt><b><span class="option">-g</span> <em class="replaceable">subroutine</em></b></dt><dd><p>Ignore subroutines except <em class="replaceable">subroutine</em> and whatever is called from it.</p></dd></dl><p><a name="INDEX-"></a>Other options are described in <em class="emphasis">dprofpp</em>(1), its standard manpage.</p><p><a name="INDEX-3659"></a><a name="INDEX-3660"></a><tt class="literal">DProf</tt> is not your only choice for profiler. CPAN also holds<tt class="literal">Devel::SmallProf</tt>, which reports the time spent in each lineof your program. That can help you figure out if you're usingsome particular Perl construct that is being surprisingly expensive.Most of the built-in functions are pretty efficient, but it's easy to accidentally write a regular expression whose overheadincreases exponentially with the size of the input. See also the section <a href="ch24_02.htm#ch24-sect-eff">Section 20.2, "Efficiency"</a> in <a href="ch24_01.htm">Chapter 24, "Common Practices"</a>, for otherhelpful hints.</p><p>Now go take that coffee break. You'll need it for the next chapter.<a name="INDEX-3661"></a><a name="INDEX-3662"></a></p><!-- BOTTOM NAV BAR --><hr width="515" align="left"><div class="navbar"><table width="515" border="0"><tr><td align="left" valign="top" width="172"><a href="ch20_05.htm"><img src="../gifs/txtpreva.gif" alt="Previous" border="0"></a></td><td align="center" valign="top" width="171"><a href="index.htm"><img src="../gifs/txthome.gif" alt="Home" border="0"></a></td><td align="right" valign="top" width="172"><a href="ch21_01.htm"><img src="../gifs/txtnexta.gif" alt="Next" border="0"></a></td></tr><tr><td align="left" valign="top" width="172">20.5. Debugger Support</td><td align="center" valign="top" width="171"><a href="index/index.htm"><img src="../gifs/index.gif" alt="Book Index" border="0"></a></td><td align="right" valign="top" width="172">21. Internals and Externals</td></tr></table></div><hr width="515" align="left"><!-- LIBRARY NAV BAR --><img src="../gifs/smnavbar.gif" usemap="#library-map" border="0" alt="Library Navigation Links"><p><font size="-1"><a href="copyrght.htm">Copyright © 2001</a> O'Reilly & Associates. All rights reserved.</font></p><map name="library-map"> <area shape="rect" coords="2,-1,79,99" href="../index.htm"><area shape="rect" coords="84,1,157,108" href="../perlnut/index.htm"><area shape="rect" coords="162,2,248,125" href="../prog/index.htm"><area shape="rect" coords="253,2,326,130" href="../advprog/index.htm"><area shape="rect" coords="332,1,407,112" href="../cookbook/index.htm"><area shape="rect" coords="414,2,523,103" href="../sysadmin/index.htm"></map><!-- END OF BODY --></body></html>⌨️ 快捷键说明
复制代码
Ctrl + C
搜索代码
Ctrl + F
全屏模式
F11
切换主题
Ctrl + Shift + D
显示快捷键
?
增大字号
Ctrl + =
减小字号
Ctrl + -