1use 5.006_001; 2 3=head1 NAME 4 5Devel::DProf - a Perl code profiler 6 7=head1 SYNOPSIS 8 9 perl5 -d:DProf test.pl 10 11=head1 DESCRIPTION 12 13The Devel::DProf package is a Perl code profiler. This will collect 14information on the execution time of a Perl script and of the subs in that 15script. This information can be used to determine which subroutines are 16using the most time and which subroutines are being called most often. This 17information can also be used to create an execution graph of the script, 18showing subroutine relationships. 19 20To profile a Perl script run the perl interpreter with the B<-d> debugging 21switch. The profiler uses the debugging hooks. So to profile script 22F<test.pl> the following command should be used: 23 24 perl5 -d:DProf test.pl 25 26When the script terminates (or when the output buffer is filled) the 27profiler will dump the profile information to a file called 28F<tmon.out>. A tool like I<dprofpp> can be used to interpret the 29information which is in that profile. The following command will 30print the top 15 subroutines which used the most time: 31 32 dprofpp 33 34To print an execution graph of the subroutines in the script use the 35following command: 36 37 dprofpp -T 38 39Consult L<dprofpp> for other options. 40 41=head1 PROFILE FORMAT 42 43The 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 60The first line is the magic number. The second line is the hertz value, or 61clock ticks, of the machine where the profile was collected. The third line 62is the name and version identifier of the tool which created the profile. 63The fourth line is a comment. The fifth line contains three variables 64holding the user time, system time, and realtime of the process while it was 65being profiled. The sixth line indicates the beginning of the sub 66entry/exit profile section. 67 68The 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 76With 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 110New C<$over_*> values show the measured overhead of making $over_tests 111calls to the profiler These values are used by the profiler to 112subtract the overhead from the runtimes. 113 114The lines starting with C<@> mark time passed from the previous C<@> 115line. The lines starting with C<&> introduce new subroutine I<id> and 116show the package and the subroutine name of this id. Lines starting 117with C<+>, C<-> and C<*> mark entering and exit of subroutines by 118I<id>s, and C<goto &subr>. 119 120The I<old-style> C<+>- and C<->-lines are used to mark the overhead 121related to writing to profiler-output file. 122 123=head1 AUTOLOAD 124 125When Devel::DProf finds a call to an C<&AUTOLOAD> subroutine it looks at the 126C<$AUTOLOAD> variable to find the real name of the sub being called. See 127L<perlsub/"Autoloading">. 128 129=head1 ENVIRONMENT 130 131C<PERL_DPROF_BUFFER> sets size of output buffer in words. Defaults to 2**14. 132 133C<PERL_DPROF_TICKS> sets number of ticks per second on some systems where 134a replacement for times() is used. Defaults to the value of C<HZ> macro. 135 136C<PERL_DPROF_OUT_FILE_NAME> sets the name of the output file. If not set, 137defaults to tmon.out. 138 139=head1 BUGS 140 141Builtin functions cannot be measured by Devel::DProf. 142 143With a newer Perl DProf relies on the fact that the numeric slot of 144$DB::sub contains an address of a subroutine. Excessive manipulation 145of this variable may overwrite this slot, as in 146 147 $DB::sub = 'current_sub'; 148 ... 149 $addr = $DB::sub + 0; 150 151will set this numeric slot to numeric value of the string 152C<current_sub>, i.e., to C<0>. This will cause a segfault on the exit 153from this subroutine. Note that the first assignment above does not 154change the numeric slot (it will I<mark> it as invalid, but will not 155write over it). 156 157Another problem is that if a subroutine exits using goto(LABEL), 158last(LABEL) or next(LABEL) then perl may crash or Devel::DProf will die 159with the error: 160 161 panic: Devel::DProf inconsistent subroutine return 162 163For example, this code will break under Devel::DProf: 164 165 sub foo { 166 last FOO; 167 } 168 FOO: { 169 foo(); 170 } 171 172A pattern like this is used by Test::More's skip() function, for 173example. See L<perldiag> for more details. 174 175Mail bug reports and feature requests to the perl5-porters mailing list at 176F<E<lt>perl5-porters@perl.orgE<gt>>. 177 178=head1 SEE ALSO 179 180L<perl>, L<dprofpp>, times(2) 181 182=cut 183 184# This sub is needed for calibration. 185package Devel::DProf; 186 187sub NONESUCH_noxs { 188 return $Devel::DProf::VERSION; 189} 190 191package 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 199BEGIN { $single = 0; } 200 201# This sub is needed during startup. 202sub DB { 203# print "nonXS DBDB\n"; 204} 205 206use XSLoader (); 207 208$Devel::DProf::VERSION = '20030813.00'; # this version not authorized by 209 # Dean Roehrich. See "Changes" file. 210 211XSLoader::load 'Devel::DProf', $Devel::DProf::VERSION; 212 2131; 214