Commit | Line | Data |
---|---|---|
3b825e41 | 1 | use 5.006_001; |
583a019e GS |
2 | |
3 | =head1 NAME | |
4 | ||
5 | Devel::DProf - a Perl code profiler | |
6 | ||
7 | =head1 SYNOPSIS | |
8 | ||
7d2f1258 | 9 | perl -d:DProf test.pl |
583a019e GS |
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 | ||
7d2f1258 | 24 | perl -d:DProf test.pl |
583a019e GS |
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 | ||
a1bbeb14 GA |
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. | |
583a019e GS |
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 | ||
34445a8a GS |
161 | C<PERL_DPROF_OUT_FILE_NAME> sets the name of the output file. If not set, |
162 | defaults to tmon.out. | |
163 | ||
583a019e GS |
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 | ||
7619c85e RG |
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 | ||
583a019e GS |
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 | ||
9426adcd IZ |
231 | use XSLoader (); |
232 | ||
6f154b1b | 233 | $Devel::DProf::VERSION = '20080331.00'; # this version not authorized by |
e9d8cdc0 | 234 | # Dean Roehrich. See "Changes" file. |
583a019e | 235 | |
9426adcd | 236 | XSLoader::load 'Devel::DProf', $Devel::DProf::VERSION; |
583a019e GS |
237 | |
238 | 1; |