| 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>perl5-porters@perl.orgE<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; |