1Devel::DProf(3pm) Perl Programmers Reference Guide Devel::DProf(3pm)
2
6 Devel::DProf - a Perl code profiler
7
9 perl -d:DProf test.pl
10
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 subrou‐
15 tines are using the most time and which subroutines are being called
16 most often. This information can also be used to create an execution
17 graph of the script, showing subroutine relationships.
18 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 perl -d:DProf test.pl
24 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 subrou‐
29 tines which used the most time:
30 dprofpp
32 To print an execution graph of the subroutines in the script use the
34 following command:
35 dprofpp -T
37 Consult dprofpp for other options.
39
41 The old profile is a text file which looks like this:
42 #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 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 real‐
63 time of the process while it was being profiled. The sixth line indi‐
64 cates the beginning of the sub entry/exit profile section.
65 The columns in PART2 are:
67 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 With newer perls another format is used, which may look like this:
75 #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 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 (with high value of $ENV{PERL_DPROF_TICKS}).
107 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 The lines starting with "@" mark time passed from the previous "@"
113 line. The lines starting with "&" introduce new subroutine id and show
114 the package and the subroutine name of this id. Lines starting with
115 "+", "-" and "*" mark entering and exit of subroutines by ids, and
116 "goto &subr".
117 The old-style "+"- and "-"-lines are used to mark the overhead related
119 to writing to profiler-output file.
120
122 When Devel::DProf finds a call to an &AUTOLOAD subroutine it looks at
123 the $AUTOLOAD variable to find the real name of the sub being called.
124 See "Autoloading" in perlsub.
125
127 "PERL_DPROF_BUFFER" sets size of output buffer in words. Defaults to
128 2**14.
129 "PERL_DPROF_TICKS" sets number of ticks per second on some systems
131 where a replacement for times() is used. Defaults to the value of "HZ"
132 macro.
133 "PERL_DPROF_OUT_FILE_NAME" sets the name of the output file. If not
135 set, defaults to tmon.out.
136
138 Builtin functions cannot be measured by Devel::DProf.
139 With a newer Perl DProf relies on the fact that the numeric slot of
141 $DB::sub contains an address of a subroutine. Excessive manipulation
142 of this variable may overwrite this slot, as in
143 $DB::sub = 'current_sub';
145 ...
146 $addr = $DB::sub + 0;
147 will set this numeric slot to numeric value of the string "cur‐
149 rent_sub", i.e., to 0. This will cause a segfault on the exit from
150 this subroutine. Note that the first assignment above does not change
151 the numeric slot (it will mark it as invalid, but will not write over
152 it).
153 Another problem is that if a subroutine exits using goto(LABEL),
155 last(LABEL) or next(LABEL) then perl may crash or Devel::DProf will die
156 with the error:
157 panic: Devel::DProf inconsistent subroutine return
159 For example, this code will break under Devel::DProf:
161 sub foo {
163 last FOO;
164 }
165 FOO: {
166 foo();
167 }
168 A pattern like this is used by Test::More's skip() function, for exam‐
170 ple. See perldiag for more details.
171 Mail bug reports and feature requests to the perl5-porters mailing list
173 at <perl5-porters@perl.org>.
174
176 perl, dprofpp, times(2)
177perl v5.8.8 2001-09-21 Devel::DProf(3pm)