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 | The lines starting with C<@> mark time passed from the previous C<@>
|
---|
115 | line. The lines starting with C<&> introduce new subroutine I<id> and
|
---|
116 | show the package and the subroutine name of this id. Lines starting
|
---|
117 | with C<+>, C<-> and C<*> mark entering and exit of subroutines by
|
---|
118 | I<id>s, and C<goto &subr>.
|
---|
119 |
|
---|
120 | The I<old-style> C<+>- and C<->-lines are used to mark the overhead
|
---|
121 | related to writing to profiler-output file.
|
---|
122 |
|
---|
123 | =head1 AUTOLOAD
|
---|
124 |
|
---|
125 | When Devel::DProf finds a call to an C<&AUTOLOAD> subroutine it looks at the
|
---|
126 | C<$AUTOLOAD> variable to find the real name of the sub being called. See
|
---|
127 | L<perlsub/"Autoloading">.
|
---|
128 |
|
---|
129 | =head1 ENVIRONMENT
|
---|
130 |
|
---|
131 | C<PERL_DPROF_BUFFER> sets size of output buffer in words. Defaults to 2**14.
|
---|
132 |
|
---|
133 | C<PERL_DPROF_TICKS> sets number of ticks per second on some systems where
|
---|
134 | a replacement for times() is used. Defaults to the value of C<HZ> macro.
|
---|
135 |
|
---|
136 | C<PERL_DPROF_OUT_FILE_NAME> sets the name of the output file. If not set,
|
---|
137 | defaults to tmon.out.
|
---|
138 |
|
---|
139 | =head1 BUGS
|
---|
140 |
|
---|
141 | Builtin functions cannot be measured by Devel::DProf.
|
---|
142 |
|
---|
143 | With a newer Perl DProf relies on the fact that the numeric slot of
|
---|
144 | $DB::sub contains an address of a subroutine. Excessive manipulation
|
---|
145 | of this variable may overwrite this slot, as in
|
---|
146 |
|
---|
147 | $DB::sub = 'current_sub';
|
---|
148 | ...
|
---|
149 | $addr = $DB::sub + 0;
|
---|
150 |
|
---|
151 | will set this numeric slot to numeric value of the string
|
---|
152 | C<current_sub>, i.e., to C<0>. This will cause a segfault on the exit
|
---|
153 | from this subroutine. Note that the first assignment above does not
|
---|
154 | change the numeric slot (it will I<mark> it as invalid, but will not
|
---|
155 | write over it).
|
---|
156 |
|
---|
157 | Another problem is that if a subroutine exits using goto(LABEL),
|
---|
158 | last(LABEL) or next(LABEL) then perl may crash or Devel::DProf will die
|
---|
159 | with the error:
|
---|
160 |
|
---|
161 | panic: Devel::DProf inconsistent subroutine return
|
---|
162 |
|
---|
163 | For example, this code will break under Devel::DProf:
|
---|
164 |
|
---|
165 | sub foo {
|
---|
166 | last FOO;
|
---|
167 | }
|
---|
168 | FOO: {
|
---|
169 | foo();
|
---|
170 | }
|
---|
171 |
|
---|
172 | A pattern like this is used by Test::More's skip() function, for
|
---|
173 | example. See L<perldiag> for more details.
|
---|
174 |
|
---|
175 | Mail bug reports and feature requests to the perl5-porters mailing list at
|
---|
176 | F<E<lt>[email protected]<gt>>.
|
---|
177 |
|
---|
178 | =head1 SEE ALSO
|
---|
179 |
|
---|
180 | L<perl>, L<dprofpp>, times(2)
|
---|
181 |
|
---|
182 | =cut
|
---|
183 |
|
---|
184 | # This sub is needed for calibration.
|
---|
185 | package Devel::DProf;
|
---|
186 |
|
---|
187 | sub NONESUCH_noxs {
|
---|
188 | return $Devel::DProf::VERSION;
|
---|
189 | }
|
---|
190 |
|
---|
191 | package DB;
|
---|
192 |
|
---|
193 | #
|
---|
194 | # As of perl5.003_20, &DB::sub stub is not needed (some versions
|
---|
195 | # even had problems if stub was redefined with XS version).
|
---|
196 | #
|
---|
197 |
|
---|
198 | # disable DB single-stepping
|
---|
199 | BEGIN { $single = 0; }
|
---|
200 |
|
---|
201 | # This sub is needed during startup.
|
---|
202 | sub DB {
|
---|
203 | # print "nonXS DBDB\n";
|
---|
204 | }
|
---|
205 |
|
---|
206 | use XSLoader ();
|
---|
207 |
|
---|
208 | $Devel::DProf::VERSION = '20050603.00'; # this version not authorized by
|
---|
209 | # Dean Roehrich. See "Changes" file.
|
---|
210 |
|
---|
211 | XSLoader::load 'Devel::DProf', $Devel::DProf::VERSION;
|
---|
212 |
|
---|
213 | 1;
|
---|