This is a live mirror of the Perl 5 development currently hosted at https://github.com/perl/perl5
Improved description of the tmon.out format.
[perl5.git] / ext / Devel / DProf / DProf.pm
1 use 5.006_001;
2
3 =head1 NAME
4
5 Devel::DProf - a Perl code profiler
6
7 =head1 SYNOPSIS
8
9         perl -d:DProf test.pl
10
11 =head1 DESCRIPTION
12
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.
19
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:
23
24         perl -d:DProf test.pl
25
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:
31
32         dprofpp
33
34 To print an execution graph of the subroutines in the script use the
35 following command:
36
37         dprofpp -T
38
39 Consult L<dprofpp> for other options.
40
41 =head1 PROFILE FORMAT
42
43 The old profile is a text file which looks like this:
44
45         #fOrTyTwO
46         $hz=100;
47         $XS_VERSION='DProf 19970606';
48         # All values are given in HZ
49         $rrun_utime=2; $rrun_stime=0; $rrun_rtime=7
50         PART2
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
58         [....]
59
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.
67
68 The columns in B<PART2> are:
69
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
75
76 With newer perls another format is used, which may look like this:
77
78         #fOrTyTwO
79         $hz=10000;
80         $XS_VERSION='DProf 19971213';
81         # All values are given in HZ
82         $over_utime=5917; $over_stime=0; $over_rtime=5917;
83         $over_tests=10000;
84         $rrun_utime=1284; $rrun_stime=0; $rrun_rtime=1284;
85         $total_marks=6;
86
87         PART2
88         @ 406 0 406
89         & 2 main bar
90         + 2
91         @ 456 0 456
92         - 2
93         @ 1 0 1
94         & 3 main baz
95         + 3
96         @ 141 0 141
97         + 2
98         @ 141 0 141
99         - 2
100         @ 1 0 1
101         & 4 main foo
102         + 4
103         @ 142 0 142
104         + & Devel::DProf::write
105         @ 5 0 5
106         - & Devel::DProf::write
107
108 (with high value of $ENV{PERL_DPROF_TICKS}).  
109
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.
113
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.
118
119 Lines starting with C<&> map subroutine identifiers (an integer) to
120 subroutine packages and names.  These should only occur once per
121 subroutine.
122
123 Lines starting with C<+> or C<-> mark normal entering and exit of
124 subroutines.  The number following is a reference to a subroutine
125 identifier.
126
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:
130
131         + 5
132         * 6
133         - 5
134
135 Lines starting with C</> is like C<-> but mark where subroutines are
136 exited by dying.  Example:
137
138         + 5
139         + 6
140         / 6
141         / 5
142
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
146 measurable time.
147
148 =head1 AUTOLOAD
149
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">.
153
154 =head1 ENVIRONMENT
155
156 C<PERL_DPROF_BUFFER> sets size of output buffer in words.  Defaults to 2**14.
157
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.
160
161 C<PERL_DPROF_OUT_FILE_NAME> sets the name of the output file.  If not set,
162 defaults to tmon.out.
163
164 =head1 BUGS
165
166 Builtin functions cannot be measured by Devel::DProf.
167
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
171
172   $DB::sub = 'current_sub';
173   ...
174   $addr = $DB::sub + 0;
175
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
180 write over it).
181
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
184 with the error:
185
186    panic: Devel::DProf inconsistent subroutine return
187
188 For example, this code will break under Devel::DProf:
189
190    sub foo {
191      last FOO;
192    }
193    FOO: {
194      foo();
195    }
196
197 A pattern like this is used by Test::More's skip() function, for
198 example.  See L<perldiag> for more details.
199
200 Mail bug reports and feature requests to the perl5-porters mailing list at
201 F<E<lt>perl5-porters@perl.orgE<gt>>.
202
203 =head1 SEE ALSO
204
205 L<perl>, L<dprofpp>, times(2)
206
207 =cut
208
209 # This sub is needed for calibration.
210 package Devel::DProf;
211
212 sub NONESUCH_noxs {
213         return $Devel::DProf::VERSION;
214 }
215
216 package DB;
217
218 #
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).
221 #
222
223 # disable DB single-stepping
224 BEGIN { $single = 0; }
225
226 # This sub is needed during startup.
227 sub DB { 
228 #       print "nonXS DBDB\n";
229 }
230
231 use XSLoader ();
232
233 $Devel::DProf::VERSION = '20050603.00';  # this version not authorized by
234                                          # Dean Roehrich. See "Changes" file.
235
236 XSLoader::load 'Devel::DProf', $Devel::DProf::VERSION;
237
238 1;