[Summary view] [Print] [Text view]

   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  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.
 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  
 161  C<PERL_DPROF_OUT_FILE_NAME> sets the name of the output file.  If not set,
 162  defaults to tmon.out.
 163  
 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  
 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  
 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  
 231  use XSLoader ();
 232  
 233  $Devel::DProf::VERSION = '20050603.00';  # this version not authorized by
 234                           # Dean Roehrich. See "Changes" file.
 235  
 236  XSLoader::load 'Devel::DProf', $Devel::DProf::VERSION;
 237  
 238  1;