Devel::DProf(3pm)

1DProf(3)              User Contributed Perl Documentation             DProf(3)
2
3
4

NAME

6       Devel::DProf - a DEPRECATED Perl code profiler
7

SYNOPSIS

9               perl -d:DProf test.pl
10

ACHTUNG!

12       "Devel::DProf" is DEPRECATED and will be removed from a future version
13       of Perl. We strongly recommend that you install and use Devel::NYTProf
14       instead, as it offers significantly improved profiling and reporting.
15

DESCRIPTION

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

PROFILE FORMAT

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

AUTOLOAD

152       When Devel::DProf finds a call to an &AUTOLOAD subroutine it looks at
153       the $AUTOLOAD variable to find the real name of the sub being called.
154       See "Autoloading" in perlsub.
155

ENVIRONMENT

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

BUGS

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