5 Devel::DProf - a Perl code profiler
13 The Devel::DProf package is a Perl code profiler. This will collect
14 information on the execution time of a Perl script and of the subs in that
15 script. This information can be used to determine which subroutines are
16 using the most time and which subroutines are being called most often. This
17 information can also be used to create an execution graph of the script,
18 showing subroutine relationships.
20 To profile a Perl script run the perl interpreter with the B<-d> debugging
21 switch. The profiler uses the debugging hooks. So to profile script
22 F<test.pl> the following command should be used:
26 When the script terminates (or when the output buffer is filled) the
27 profiler will dump the profile information to a file called
28 F<tmon.out>. A tool like I<dprofpp> can be used to interpret the
29 information which is in that profile. The following command will
30 print the top 15 subroutines which used the most time:
34 To print an execution graph of the subroutines in the script use the
39 Consult L<dprofpp> for other options.
43 The old profile is a text file which looks like this:
47 $XS_VERSION='DProf 19970606';
48 # All values are given in HZ
49 $rrun_utime=2; $rrun_stime=0; $rrun_rtime=7
51 + 26 28 566822884 DynaLoader::import
52 - 26 28 566822884 DynaLoader::import
53 + 27 28 566822885 main::bar
54 - 27 28 566822886 main::bar
55 + 27 28 566822886 main::baz
56 + 27 28 566822887 main::bar
57 - 27 28 566822888 main::bar
60 The first line is the magic number. The second line is the hertz value, or
61 clock ticks, of the machine where the profile was collected. The third line
62 is the name and version identifier of the tool which created the profile.
63 The fourth line is a comment. The fifth line contains three variables
64 holding the user time, system time, and realtime of the process while it was
65 being profiled. The sixth line indicates the beginning of the sub
66 entry/exit profile section.
68 The columns in B<PART2> are:
70 sub entry(+)/exit(-) mark
71 app's user time at sub entry/exit mark, in ticks
72 app's system time at sub entry/exit mark, in ticks
73 app's realtime at sub entry/exit mark, in ticks
74 fully-qualified sub name, when possible
76 With newer perls another format is used, which may look like this:
80 $XS_VERSION='DProf 19971213';
81 # All values are given in HZ
82 $over_utime=5917; $over_stime=0; $over_rtime=5917;
84 $rrun_utime=1284; $rrun_stime=0; $rrun_rtime=1284;
104 + & Devel::DProf::write
106 - & Devel::DProf::write
108 (with high value of $ENV{PERL_DPROF_TICKS}).
110 New C<$over_*> values show the measured overhead of making $over_tests
111 calls to the profiler These values are used by the profiler to
112 subtract the overhead from the runtimes.
114 Lines starting with C<@> mark the amount of time passed since the
115 previous C<@> line. The numbers following the C<@> are integer tick
116 counts representing user, system, and real time. Divide these numbers
117 by the $hz value in the header to get seconds.
119 Lines starting with C<&> map subroutine identifiers (an integer) to
120 subroutine packages and names. These should only occur once per
123 Lines starting with C<+> or C<-> mark normal entering and exit of
124 subroutines. The number following is a reference to a subroutine
127 Lines starting with C<*> mark where subroutines are entered by C<goto
128 &subr>, but note that the return will still be marked as coming from
129 the original sub. The sequence might look like this:
135 Lines starting with C</> is like C<-> but mark where subroutines are
136 exited by dying. Example:
143 Finally you might find C<@> time stamp marks surrounded by C<+ &
144 Devel::DProf::write> and C<- & Devel::DProf::write> lines. These 3
145 lines are outputted when printing of the mark above actually consumed
150 When Devel::DProf finds a call to an C<&AUTOLOAD> subroutine it looks at the
151 C<$AUTOLOAD> variable to find the real name of the sub being called. See
152 L<perlsub/"Autoloading">.
156 C<PERL_DPROF_BUFFER> sets size of output buffer in words. Defaults to 2**14.
158 C<PERL_DPROF_TICKS> sets number of ticks per second on some systems where
159 a replacement for times() is used. Defaults to the value of C<HZ> macro.
161 C<PERL_DPROF_OUT_FILE_NAME> sets the name of the output file. If not set,
162 defaults to tmon.out.
166 Builtin functions cannot be measured by Devel::DProf.
168 With a newer Perl DProf relies on the fact that the numeric slot of
169 $DB::sub contains an address of a subroutine. Excessive manipulation
170 of this variable may overwrite this slot, as in
172 $DB::sub = 'current_sub';
174 $addr = $DB::sub + 0;
176 will set this numeric slot to numeric value of the string
177 C<current_sub>, i.e., to C<0>. This will cause a segfault on the exit
178 from this subroutine. Note that the first assignment above does not
179 change the numeric slot (it will I<mark> it as invalid, but will not
182 Another problem is that if a subroutine exits using goto(LABEL),
183 last(LABEL) or next(LABEL) then perl may crash or Devel::DProf will die
186 panic: Devel::DProf inconsistent subroutine return
188 For example, this code will break under Devel::DProf:
197 A pattern like this is used by Test::More's skip() function, for
198 example. See L<perldiag> for more details.
200 Mail bug reports and feature requests to the perl5-porters mailing list at
201 F<E<lt>perl5-porters@perl.orgE<gt>>.
205 L<perl>, L<dprofpp>, times(2)
209 # This sub is needed for calibration.
210 package Devel::DProf;
213 return $Devel::DProf::VERSION;
219 # As of perl5.003_20, &DB::sub stub is not needed (some versions
220 # even had problems if stub was redefined with XS version).
223 # disable DB single-stepping
224 BEGIN { $single = 0; }
226 # This sub is needed during startup.
228 # print "nonXS DBDB\n";
233 $Devel::DProf::VERSION = '20050603.00'; # this version not authorized by
234 # Dean Roehrich. See "Changes" file.
236 XSLoader::load 'Devel::DProf', $Devel::DProf::VERSION;