1Devel::DProf(3pm)      Perl Programmers Reference Guide      Devel::DProf(3pm)
2
3
4

NAME

6       Devel::DProf - a Perl code profiler
7

SYNOPSIS

9               perl -d:DProf test.pl
10

DESCRIPTION

12       The Devel::DProf package is a Perl code profiler.  This will collect
13       information on the execution time of a Perl script and of the subs in
14       that script.  This information can be used to determine which
15       subroutines are using the most time and which subroutines are being
16       called most often.  This information can also be used to create an
17       execution graph of the script, showing subroutine relationships.
18
19       To profile a Perl script run the perl interpreter with the -d debugging
20       switch.  The profiler uses the debugging hooks.  So to profile script
21       test.pl the following command should be used:
22
23               perl -d:DProf test.pl
24
25       When the script terminates (or when the output buffer is filled) the
26       profiler will dump the profile information to a file called tmon.out.
27       A tool like dprofpp can be used to interpret the information which is
28       in that profile.  The following command will print the top 15
29       subroutines which used the most time:
30
31               dprofpp
32
33       To print an execution graph of the subroutines in the script use the
34       following command:
35
36               dprofpp -T
37
38       Consult dprofpp for other options.
39

PROFILE FORMAT

41       The old profile is a text file which looks like this:
42
43               #fOrTyTwO
44               $hz=100;
45               $XS_VERSION='DProf 19970606';
46               # All values are given in HZ
47               $rrun_utime=2; $rrun_stime=0; $rrun_rtime=7
48               PART2
49               + 26 28 566822884 DynaLoader::import
50               - 26 28 566822884 DynaLoader::import
51               + 27 28 566822885 main::bar
52               - 27 28 566822886 main::bar
53               + 27 28 566822886 main::baz
54               + 27 28 566822887 main::bar
55               - 27 28 566822888 main::bar
56               [....]
57
58       The first line is the magic number.  The second line is the hertz
59       value, or clock ticks, of the machine where the profile was collected.
60       The third line is the name and version identifier of the tool which
61       created the profile.  The fourth line is a comment.  The fifth line
62       contains three variables holding the user time, system time, and
63       realtime of the process while it was being profiled.  The sixth line
64       indicates the beginning of the sub entry/exit profile section.
65
66       The columns in PART2 are:
67
68               sub entry(+)/exit(-) mark
69               app's user time at sub entry/exit mark, in ticks
70               app's system time at sub entry/exit mark, in ticks
71               app's realtime at sub entry/exit mark, in ticks
72               fully-qualified sub name, when possible
73
74       With newer perls another format is used, which may look like this:
75
76               #fOrTyTwO
77               $hz=10000;
78               $XS_VERSION='DProf 19971213';
79               # All values are given in HZ
80               $over_utime=5917; $over_stime=0; $over_rtime=5917;
81               $over_tests=10000;
82               $rrun_utime=1284; $rrun_stime=0; $rrun_rtime=1284;
83               $total_marks=6;
84
85               PART2
86               @ 406 0 406
87               & 2 main bar
88               + 2
89               @ 456 0 456
90               - 2
91               @ 1 0 1
92               & 3 main baz
93               + 3
94               @ 141 0 141
95               + 2
96               @ 141 0 141
97               - 2
98               @ 1 0 1
99               & 4 main foo
100               + 4
101               @ 142 0 142
102               + & Devel::DProf::write
103               @ 5 0 5
104               - & Devel::DProf::write
105
106       (with high value of $ENV{PERL_DPROF_TICKS}).
107
108       New "$over_*" values show the measured overhead of making $over_tests
109       calls to the profiler These values are used by the profiler to subtract
110       the overhead from the runtimes.
111
112       Lines starting with "@" mark the amount of time passed since the
113       previous "@" line.  The numbers following the "@" are integer tick
114       counts representing user, system, and real time.  Divide these numbers
115       by the $hz value in the header to get seconds.
116
117       Lines starting with "&" map subroutine identifiers (an integer) to
118       subroutine packages and names.  These should only occur once per
119       subroutine.
120
121       Lines starting with "+" or "-" mark normal entering and exit of
122       subroutines.  The number following is a reference to a subroutine
123       identifier.
124
125       Lines starting with "*" mark where subroutines are entered by "goto
126       &subr", but note that the return will still be marked as coming from
127       the original sub.  The sequence might look like this:
128
129               + 5
130               * 6
131               - 5
132
133       Lines starting with "/" is like "-" but mark where subroutines are
134       exited by dying.  Example:
135
136               + 5
137               + 6
138               / 6
139               / 5
140
141       Finally you might find "@" time stamp marks surrounded by "+ &
142       Devel::DProf::write" and "- & Devel::DProf::write" lines.  These 3
143       lines are outputted when printing of the mark above actually consumed
144       measurable time.
145

AUTOLOAD

147       When Devel::DProf finds a call to an &AUTOLOAD subroutine it looks at
148       the $AUTOLOAD variable to find the real name of the sub being called.
149       See "Autoloading" in perlsub.
150

ENVIRONMENT

152       "PERL_DPROF_BUFFER" sets size of output buffer in words.  Defaults to
153       2**14.
154
155       "PERL_DPROF_TICKS" sets number of ticks per second on some systems
156       where a replacement for times() is used.  Defaults to the value of "HZ"
157       macro.
158
159       "PERL_DPROF_OUT_FILE_NAME" sets the name of the output file.  If not
160       set, defaults to tmon.out.
161

BUGS

163       Builtin functions cannot be measured by Devel::DProf.
164
165       With a newer Perl DProf relies on the fact that the numeric slot of
166       $DB::sub contains an address of a subroutine.  Excessive manipulation
167       of this variable may overwrite this slot, as in
168
169         $DB::sub = 'current_sub';
170         ...
171         $addr = $DB::sub + 0;
172
173       will set this numeric slot to numeric value of the string
174       "current_sub", i.e., to 0.  This will cause a segfault on the exit from
175       this subroutine.  Note that the first assignment above does not change
176       the numeric slot (it will mark it as invalid, but will not write over
177       it).
178
179       Another problem is that if a subroutine exits using goto(LABEL),
180       last(LABEL) or next(LABEL) then perl may crash or Devel::DProf will die
181       with the error:
182
183          panic: Devel::DProf inconsistent subroutine return
184
185       For example, this code will break under Devel::DProf:
186
187          sub foo {
188            last FOO;
189          }
190          FOO: {
191            foo();
192          }
193
194       A pattern like this is used by Test::More's skip() function, for
195       example.  See perldiag for more details.
196
197       Mail bug reports and feature requests to the perl5-porters mailing list
198       at <perl5-porters@perl.org>.
199

SEE ALSO

201       perl, dprofpp, times(2)
202
203
204
205perl v5.12.4                      2011-06-08                 Devel::DProf(3pm)
Impressum