source: trunk/third/perl/utils/dprofpp.PL @ 14545

Revision 14545, 21.7 KB checked in by ghudson, 24 years ago (diff)
This commit was generated by cvs2svn to compensate for changes in r14544, which included commits to RCS files with non-trunk default branches.
Line 
1#!/usr/local/bin/perl
2
3use Config;
4use File::Basename qw(&basename &dirname);
5
6# List explicitly here the variables you want Configure to
7# generate.  Metaconfig only looks for shell variables, so you
8# have to mention them as if they were shell variables, not
9# %Config entries.  Thus you write
10#  $startperl
11# to ensure Configure will look for $Config{startperl}.
12
13# This forces PL files to create target in same directory as PL file.
14# This is so that make depend always knows where to find PL derivatives.
15chdir(dirname($0));
16($file = basename($0)) =~ s/\.PL$//;
17$file =~ s/\.pl$// if ($Config{'osname'} eq 'OS2');      # "case-forgiving"
18$file =~ s/\.pl$/.com/ if ($Config{'osname'} eq 'VMS');  # "case-forgiving"
19
20my $dprof_pm = '../ext/Devel/DProf/DProf.pm';
21my $VERSION = 0;
22open( PM, "<$dprof_pm" ) || die "Can't open $dprof_pm: $!";
23while(<PM>){
24        if( /^\$Devel::DProf::VERSION\s*=\s*'([\d._]+)'/ ){
25                $VERSION = $1;
26                last;
27        }
28}
29close PM;
30if( $VERSION == 0 ){
31        die "Did not find VERSION in $dprof_pm";
32}
33open OUT,">$file" or die "Can't create $file: $!";
34
35print "Extracting $file (with variable substitutions)\n";
36
37# In this section, perl variables will be expanded during extraction.
38# You can use $Config{...} to use Configure variables.
39
40print OUT <<"!GROK!THIS!";
41$Config{'startperl'}
42    eval 'exec perl -S \$0 "\$@"'
43        if 0;
44
45require 5.003;
46
47my \$VERSION = '$VERSION';
48
49!GROK!THIS!
50
51# In the following, perl variables are not expanded during extraction.
52
53print OUT <<'!NO!SUBS!';
54=head1 NAME
55
56dprofpp - display perl profile data
57
58=head1 SYNOPSIS
59
60dprofpp [B<-a>|B<-z>|B<-l>|B<-v>|B<-U>] [B<-s>|B<-r>|B<-u>] [B<-q>] [B<-F>] [B<-I|-E>] [B<-O cnt>] [B<-A>] [B<-R>] [B<-S>] [B<-g subroutine>] [profile]
61
62dprofpp B<-T> [B<-F>] [B<-g subroutine>] [profile]
63
64dprofpp B<-t> [B<-F>] [B<-g subroutine>] [profile]
65
66dprofpp B<-p script> [B<-Q>] [other opts]
67
68dprofpp B<-V> [profile]
69
70=head1 DESCRIPTION
71
72The I<dprofpp> command interprets profile data produced by a profiler, such
73as the Devel::DProf profiler.  Dprofpp will read the file F<tmon.out> and
74will display the 15 subroutines which are using the most time.  By default
75the times for each subroutine are given exclusive of the times of their
76child subroutines.
77
78To profile a Perl script run the perl interpreter with the B<-d> switch.  So
79to profile script F<test.pl> with Devel::DProf the following command should
80be used.
81
82        $ perl5 -d:DProf test.pl
83
84Then run dprofpp to analyze the profile.  The output of dprofpp depends
85on the flags to the program and the version of Perl you're using.
86
87        $ dprofpp -u
88        Total Elapsed Time =    1.67 Seconds
89                 User Time =    0.61 Seconds
90        Exclusive Times
91        %Time Seconds     #Calls sec/call Name
92         52.4   0.320          2   0.1600 main::foo
93         45.9   0.280        200   0.0014 main::bar
94         0.00   0.000          1   0.0000 DynaLoader::import
95         0.00   0.000          1   0.0000 main::baz
96
97The dprofpp tool can also run the profiler before analyzing the profile
98data.  The above two commands can be executed with one dprofpp command.
99
100        $ dprofpp -u -p test.pl
101
102Consult L<Devel::DProf/"PROFILE FORMAT"> for a description of the raw profile.
103
104=head1 OUTPUT
105
106Columns are:
107
108=over 4
109
110=item %Time
111
112Percentage of time spent in this routine.
113
114=item #Calls
115
116Number of calls to this routine.
117
118=item sec/call
119
120Average number of seconds per call to this routine.
121
122=item Name
123
124Name of routine.
125
126=item CumulS
127
128Time (in seconds) spent in this routine and routines called from it.
129
130=item ExclSec
131
132Time (in seconds) spent in this routine (not including those called
133from it).
134
135=item Csec/c
136
137Average time (in seconds) spent in each call of this routine
138(including those called from it).
139
140=back
141
142=head1 OPTIONS
143
144=over 5
145
146=item B<-a>
147
148Sort alphabetically by subroutine names.
149
150=item B<-A>
151
152Count timing for autoloaded subroutine as timing for C<*::AUTOLOAD>.
153Otherwise the time to autoload it is counted as time of the subroutine
154itself (there is no way to separate autoload time from run time).
155
156This is going to be irrelevant with newer Perls.  They will inform
157C<Devel::DProf> I<when> the C<AUTOLOAD> switches to actual subroutine,
158so a separate statistics for C<AUTOLOAD> will be collected no matter
159whether this option is set.
160
161=item B<-R>
162
163Count anonymous subroutines defined in the same package separately.
164
165=item B<-E>
166
167(default)  Display all subroutine times exclusive of child subroutine times.
168
169=item B<-F>
170
171Force the generation of fake exit timestamps if dprofpp reports that the
172profile is garbled.  This is only useful if dprofpp determines that the
173profile is garbled due to missing exit timestamps.  You're on your own if
174you do this.  Consult the BUGS section.
175
176=item B<-I>
177
178Display all subroutine times inclusive of child subroutine times.
179
180=item B<-l>
181
182Sort by number of calls to the subroutines.  This may help identify
183candidates for inlining.
184
185=item B<-O cnt>
186
187Show only I<cnt> subroutines.  The default is 15.
188
189=item B<-p script>
190
191Tells dprofpp that it should profile the given script and then interpret its
192profile data.  See B<-Q>.
193
194=item B<-Q>
195
196Used with B<-p> to tell dprofpp to quit after profiling the script, without
197interpreting the data.
198
199=item B<-q>
200
201Do not display column headers.
202
203=item B<-r>
204
205Display elapsed real times rather than user+system times.
206
207=item B<-s>
208
209Display system times rather than user+system times.
210
211=item B<-T>
212
213Display subroutine call tree to stdout.  Subroutine statistics are
214not displayed.
215
216=item B<-t>
217
218Display subroutine call tree to stdout.  Subroutine statistics are not
219displayed.  When a function is called multiple consecutive times at the same
220calling level then it is displayed once with a repeat count.
221
222=item B<-S>
223
224Display I<merged> subroutine call tree to stdout.  Statistics is
225displayed for each branch of the tree. 
226
227When a function is called multiple (I<not necessarily consecutive>)
228times in the same branch then all these calls go into one branch of
229the next level.  A repeat count is output together with combined
230inclusive, exclusive and kids time.
231
232Branches are sorted w.r.t. inclusive time.
233
234=item B<-U>
235
236Do not sort.  Display in the order found in the raw profile.
237
238=item B<-u>
239
240Display user times rather than user+system times.
241
242=item B<-V>
243
244Print dprofpp's version number and exit.  If a raw profile is found then its
245XS_VERSION variable will be displayed, too.
246
247=item B<-v>
248
249Sort by average time spent in subroutines during each call.  This may help
250identify candidates for inlining.
251
252=item B<-z>
253
254(default) Sort by amount of user+system time used.  The first few lines
255should show you which subroutines are using the most time.
256
257=item B<-g> C<subroutine>
258
259Ignore subroutines except C<subroutine> and whatever is called from it.
260
261=back
262
263=head1 ENVIRONMENT
264
265The environment variable B<DPROFPP_OPTS> can be set to a string containing
266options for dprofpp.  You might use this if you prefer B<-I> over B<-E> or
267if you want B<-F> on all the time.
268
269This was added fairly lazily, so there are some undesirable side effects.
270Options on the commandline should override options in DPROFPP_OPTS--but
271don't count on that in this version.
272
273=head1 BUGS
274
275Applications which call _exit() or exec() from within a subroutine
276will leave an incomplete profile.  See the B<-F> option.
277
278Any bugs in Devel::DProf, or any profiler generating the profile data, could
279be visible here.  See L<Devel::DProf/BUGS>.
280
281Mail bug reports and feature requests to the perl5-porters mailing list at
282F<E<lt>perl5-porters@perl.orgE<gt>>.  Bug reports should include the
283output of the B<-V> option.
284
285=head1 FILES
286
287        dprofpp         - profile processor
288        tmon.out        - raw profile
289
290=head1 SEE ALSO
291
292L<perl>, L<Devel::DProf>, times(2)
293
294=cut
295
296use Getopt::Std 'getopts';
297use Config '%Config';
298
299Setup: {
300        my $options = 'O:g:lzaAvuTtqrRsUFEIp:QVS';
301
302        $Monfile = 'tmon.out';
303        if( exists $ENV{DPROFPP_OPTS} ){
304                my @tmpargv = @ARGV;
305                @ARGV = split( ' ', $ENV{DPROFPP_OPTS} );
306                getopts( $options );
307                if( @ARGV ){
308                        # there was a filename.
309                        $Monfile = shift;
310                }
311                @ARGV = @tmpargv;
312        }
313
314        getopts( $options );
315        if( @ARGV ){
316                # there was a filename, it overrides any earlier name.
317                $Monfile = shift;
318        }
319
320# -O cnt        Specifies maximum number of subroutines to display.
321# -a            Sort by alphabetic name of subroutines.
322# -z            Sort by user+system time spent in subroutines. (default)
323# -l            Sort by number of calls to subroutines.
324# -v            Sort by average amount of time spent in subroutines.
325# -T            Show call tree.
326# -t            Show call tree, compressed.
327# -q            Do not print column headers.
328# -u            Use user time rather than user+system time.
329# -s            Use system time rather than user+system time.
330# -r            Use real elapsed time rather than user+system time.
331# -U            Do not sort subroutines.
332# -E            Sub times are reported exclusive of child times. (default)
333# -I            Sub times are reported inclusive of child times.
334# -V            Print dprofpp's version.
335# -p script     Specifies name of script to be profiled.
336# -Q            Used with -p to indicate the dprofpp should quit after
337#               profiling the script, without interpreting the data.
338# -A            count autoloaded to *AUTOLOAD
339# -R            count anonyms separately even if from the same package
340# -g subr       count only those who are SUBR or called from SUBR
341# -S            Create statistics for all the depths
342
343        if( defined $opt_V ){
344                my $fh = 'main::fh';
345                print "$0 version: $VERSION\n";
346                open( $fh, "<$Monfile" ) && do {
347                        local $XS_VERSION = 'early';
348                        header($fh);
349                        close( $fh );
350                        print "XS_VERSION: $XS_VERSION\n";
351                };
352                exit(0);
353        }
354        $cnt = $opt_O || 15;
355        $sort = 'by_time';
356        $sort = 'by_ctime' if defined $opt_I;
357        $sort = 'by_calls' if defined $opt_l;
358        $sort = 'by_alpha' if defined $opt_a;
359        $sort = 'by_avgcpu' if defined $opt_v;
360        $incl_excl = 'Exclusive';
361        $incl_excl = 'Inclusive' if defined $opt_I;
362        $whichtime = 'User+System';
363        $whichtime = 'System' if defined $opt_s;
364        $whichtime = 'Real' if defined $opt_r;
365        $whichtime = 'User' if defined $opt_u;
366
367        if( defined $opt_p ){
368                my $prof = 'DProf';
369                my $startperl = $Config{'startperl'};
370
371                $startperl =~ s/^#!//; # remove shebang
372                run_profiler( $opt_p, $prof, $startperl );
373                $Monfile = 'tmon.out';  # because that's where it is
374                exit(0) if defined $opt_Q;
375        }
376        elsif( defined $opt_Q ){
377                die "-Q is meaningful only when used with -p\n";
378        }
379}
380
381Main: {
382        my $monout = $Monfile;
383        my $fh = 'main::fh';
384        local $names = {};
385        local $times = {};   # times in hz
386        local $ctimes = {};  # Cumulative times in hz
387        local $calls = {};
388        local $persecs = {}; # times in seconds
389        local $idkeys = [];
390        local $runtime; # runtime in seconds
391        my @a = ();
392        my $a;
393        local $rrun_utime = 0;  # user time in hz
394        local $rrun_stime = 0;  # system time in hz
395        local $rrun_rtime = 0;  # elapsed run time in hz
396        local $rrun_ustime = 0; # user+system time in hz
397        local $hz = 0;
398        local $deep_times = {count => 0 , kids => {}, incl_time => 0};
399        local $time_precision = 2;
400        local $overhead = 0;
401
402        open( $fh, "<$monout" ) || die "Unable to open $monout\n";
403
404        header($fh);
405
406        $rrun_ustime = $rrun_utime + $rrun_stime;
407
408        $~ = 'STAT';
409        if( ! $opt_q ){
410                $^ = 'CSTAT_top';
411        }
412
413        parsestack( $fh, $names, $calls, $times, $ctimes, $idkeys );
414
415        settime( \$runtime, $hz ) unless $opt_g;
416
417        exit(0) if $opt_T || $opt_t;
418
419        if( $opt_v ){
420                percalc( $calls, ($opt_I ? $ctimes : $times), $persecs, $idkeys );
421        }
422        if( ! $opt_U ){
423                @a = sort $sort @$idkeys;
424                $a = \@a;
425        }
426        else {
427                $a = $idkeys;
428        }
429        display( $runtime, $hz, $names, $calls, $times, $ctimes, $cnt, $a,
430                 $deep_times);
431}
432
433
434# Sets $runtime to user, system, real, or user+system time.  The
435# result is given in seconds.
436#
437sub settime {
438  my( $runtime, $hz ) = @_;
439
440  $hz ||= 1;
441 
442  if( $opt_r ){
443    $$runtime = ($rrun_rtime - $overhead - $over_rtime * $total_marks/$over_tests/2)/$hz;
444  }
445  elsif( $opt_s ){
446    $$runtime = ($rrun_stime - $overhead - $over_stime * $total_marks/$over_tests/2)/$hz;
447  }
448  elsif( $opt_u ){
449    $$runtime = ($rrun_utime - $overhead - $over_utime * $total_marks/$over_tests/2)/$hz;
450  }
451  else{
452    $$runtime = ($rrun_ustime - $overhead - ($over_utime + $over_stime) * $total_marks/$over_tests/2)/$hz;
453  }
454  $$runtime = 0 unless $$runtime > 0;
455}
456
457sub exclusives_in_tree {
458  my( $deep_times ) = @_;
459  my $kids_time = 0;
460  my $kid;
461  # When summing, take into account non-rounded-up kids time.
462  for $kid (keys %{$deep_times->{kids}}) {
463    $kids_time += $deep_times->{kids}{$kid}{incl_time};
464  }
465  $kids_time = 0 unless $kids_time >= 0;
466  $deep_times->{excl_time} = $deep_times->{incl_time} - $kids_time;
467  $deep_times->{excl_time} = 0 unless $deep_times->{excl_time} >= 0;
468  for $kid (keys %{$deep_times->{kids}}) {
469    exclusives_in_tree($deep_times->{kids}{$kid});
470  }
471  $deep_times->{incl_time} = 0 unless $deep_times->{incl_time} >= 0;
472  $deep_times->{kids_time} = $kids_time;
473}
474
475sub kids_by_incl { $kids{$b}{incl_time} <=> $kids{$a}{excl_time}
476                   or $a cmp $b }
477
478sub display_tree {
479  my( $deep_times, $name, $level ) = @_;
480  exclusives_in_tree($deep_times);
481 
482  my $kid;
483  local *kids = $deep_times->{kids}; # %kids
484
485  my $time;
486  if (%kids) {
487    $time = sprintf '%.*fs = (%.*f + %.*f)',
488      $time_precision, $deep_times->{incl_time}/$hz,
489        $time_precision, $deep_times->{excl_time}/$hz,
490          $time_precision, $deep_times->{kids_time}/$hz;
491  } else {
492    $time = sprintf '%.*f', $time_precision, $deep_times->{incl_time}/$hz;
493  }
494  print ' ' x (2*$level), "$name x $deep_times->{count}  \t${time}s\n"
495    if $deep_times->{count};
496
497  for $kid (sort kids_by_incl keys %kids) {
498    display_tree( $deep_times->{kids}{$kid}, $kid, $level + 1 );
499  } 
500}
501
502# Report the times in seconds.
503sub display {
504        my( $runtime, $hz, $names, $calls, $times, $ctimes, $cnt,
505            $idkeys, $deep_times ) = @_;
506        my( $x, $key, $s, $cs );
507        #format: $ncalls, $name, $secs, $percall, $pcnt
508
509        if ($opt_S) {
510          display_tree( $deep_times, 'toplevel', -1 )
511        } else {
512          for( $x = 0; $x < @$idkeys; ++$x ){
513            $key = $idkeys->[$x];
514            $ncalls = $calls->{$key};
515            $name = $names->{$key};
516            $s = $times->{$key}/$hz;
517            $secs = sprintf("%.3f", $s );
518            $cs = $ctimes->{$key}/$hz;
519            $csecs = sprintf("%.3f", $cs );
520            $percall = sprintf("%.4f", $s/$ncalls );
521            $cpercall = sprintf("%.4f", $cs/$ncalls );
522            $pcnt = sprintf("%.2f",
523                            $runtime? ((($opt_I ? $csecs : $secs) / $runtime) * 100.0): 0 );
524            write;
525            $pcnt = $secs = $ncalls = $percall = "";
526            write while( length $name );
527            last unless --$cnt;
528          }       
529        }
530}
531
532sub move_keys {
533  my ($source, $dest) = @_;
534  my $kid;
535 
536  for $kid (keys %$source) {
537    if (exists $dest->{$kid}) {
538      $dest->{count} += $source->{count};
539      $dest->{incl_time} += $source->{incl_time};
540      move_keys($source->{kids},$dest->{kids});
541    } else {
542      $dest->{$kid} = delete $source->{$kid};
543    }
544  }
545}
546
547sub add_to_tree {
548  my ($curdeep_times, $name, $t) = @_;
549  if ($name ne $curdeep_times->[-1]{name} and $opt_A) {
550    $name = $curdeep_times->[-1]{name};
551  }
552  die "Shorted?!" unless @$curdeep_times >= 2;
553  $curdeep_times->[-2]{kids}{$name} = { count => 0 , kids => {},
554                                        incl_time => 0,
555                                      }
556    unless exists $curdeep_times->[-2]{kids}{$name};
557  my $entry = $curdeep_times->[-2]{kids}{$name};
558  # Now transfer to the new node (could not do earlier, since name can change)
559  $entry->{count}++;
560  $entry->{incl_time} += $t - $curdeep_times->[-1]{enter_stamp};
561  # Merge the kids?
562  move_keys($curdeep_times->[-1]->{kids},$entry->{kids});
563  pop @$curdeep_times;
564}
565
566sub parsestack {
567        my( $fh, $names, $calls, $times, $ctimes, $idkeys ) = @_;
568        my( $dir, $name );
569        my( $t, $syst, $realt, $usert );
570        my( $x, $z, $c, $id, $pack );
571        my @stack = ();
572        my @tstack = ();
573        my $tab = 3;
574        my $in = 0;
575
576        # remember last call depth and function name
577        my $l_in = $in;
578        my $l_name = '';
579        my $repcnt = 0;
580        my $repstr = '';
581        my $dprof_t = 0;
582        my $dprof_stamp;
583        my %cv_hash;
584        my $in_level = not defined $opt_g; # Level deep in report grouping
585        my $curdeep_times = [$deep_times];
586
587        my $over_per_call;
588        if   ( $opt_u ) {       $over_per_call = $over_utime            }
589        elsif( $opt_s ) {       $over_per_call = $over_stime            }
590        elsif( $opt_r ) {       $over_per_call = $over_rtime            }
591        else            {       $over_per_call = $over_utime + $over_stime }
592        $over_per_call /= 2*$over_tests; # distribute over entry and exit
593
594        while(<$fh>){
595                next if /^#/;
596                last if /^PART/;
597
598                chop;
599                if (/^&/) {
600                  ($dir, $id, $pack, $name) = split;
601                  if ($opt_R and ($name =~ /::(__ANON_|END)$/)) {
602                    $name .= "($id)";
603                  }
604                  $cv_hash{$id} = "$pack\::$name";
605                  next;
606                }
607                ($dir, $usert, $syst, $realt, $name) = split;
608
609                my $ot = $t;
610                if ( $dir eq '/' ) {
611                  $syst = $stack[-1][0];
612                  $usert = '&';
613                  $dir = '-';
614                  #warn("Inserted exit for $stack[-1][0].\n")
615                }
616                if (defined $realt) { # '+ times nam' '- times nam' or '@ incr'
617                  if   ( $opt_u )       {       $t = $usert             }
618                  elsif( $opt_s )       {       $t = $syst              }
619                  elsif( $opt_r )       {       $t = $realt             }
620                  else                  {       $t = $usert + $syst     }
621                  $t += $ot, next if $dir eq '@'; # Increments there
622                } else {
623                  # "- id" or "- & name"
624                  $name = defined $syst ? $syst : $cv_hash{$usert};
625                }
626
627                next unless $in_level or $name eq $opt_g or $dir eq '*';
628                if ( $dir eq '-' or $dir eq '*' ) {
629                        my $ename = $dir eq '*' ? $stack[-1][0]  : $name;
630                        $overhead += $over_per_call;
631                        if ($name eq "Devel::DProf::write") {
632                          $dprof_t += $t - $dprof_stamp;
633                          next;
634                        } elsif (defined $opt_g and $ename eq $opt_g) {
635                          $in_level--;
636                        }
637                        add_to_tree($curdeep_times, $ename,
638                                    $t - $dprof_t - $overhead) if $opt_S;
639                        exitstamp( \@stack, \@tstack,
640                                   $t - $dprof_t - $overhead,
641                                   $times, $ctimes, $ename, \$in, $tab,
642                                   $curdeep_times );
643                }
644                next unless $in_level or $name eq $opt_g;
645                if( $dir eq '+' or $dir eq '*' ){
646                        if ($name eq "Devel::DProf::write") {
647                          $dprof_stamp = $t;
648                          next;
649                        } elsif (defined $opt_g and $name eq $opt_g) {
650                          $in_level++;
651                        }
652                        $overhead += $over_per_call;
653                        if( $opt_T ){
654                                print ' ' x $in, "$name\n";
655                                $in += $tab;
656                        }
657                        elsif( $opt_t ){
658                                # suppress output on same function if the
659                                # same calling level is called.
660                                if ($l_in == $in and $l_name eq $name) {
661                                        $repcnt++;
662                                } else {
663                                        $repstr = ' ('.++$repcnt.'x)'
664                                                 if $repcnt;
665                                        print ' ' x $l_in, "$l_name$repstr\n"
666                                                if $l_name ne '';
667                                        $repstr = '';
668                                        $repcnt = 0;
669                                        $l_in = $in;
670                                        $l_name = $name;
671                                }
672                                $in += $tab;
673                        }
674                        if( ! defined $names->{$name} ){
675                                $names->{$name} = $name;
676                                $times->{$name} = 0;
677                                $ctimes->{$name} = 0;
678                                push( @$idkeys, $name );
679                        }
680                        $calls->{$name}++;
681                        push @$curdeep_times, { kids => {},
682                                                name => $name,
683                                                enter_stamp => $t - $dprof_t - $overhead,
684                                              } if $opt_S;
685                        $x = [ $name, $t - $dprof_t - $overhead ];
686                        push( @stack, $x );
687
688                        # my children will put their time here
689                        push( @tstack, 0 );
690                } elsif ($dir ne '-'){
691                    die "Bad profile: $_";
692                }
693        }
694        if( $opt_t ){
695                $repstr = ' ('.++$repcnt.'x)' if $repcnt;
696                print ' ' x $l_in, "$l_name$repstr\n";
697        }
698
699        if( @stack ){
700                if( ! $opt_F ){
701                        warn "Garbled profile is missing some exit time stamps:\n";
702                        foreach $x (@stack) {
703                                print $x->[0],"\n";
704                        }
705                        die "Try rerunning dprofpp with -F.\n";
706                        # I don't want -F to be default behavior--yet
707                        #  9/18/95 dmr
708                }
709                else{
710                        warn( "Faking " . scalar( @stack ) . " exit timestamp(s).\n");
711                        foreach $x ( reverse @stack ){
712                                $name = $x->[0];
713                                exitstamp( \@stack, \@tstack,
714                                           $t - $dprof_t - $overhead, $times,
715                                           $ctimes, $name, \$in, $tab,
716                                           $curdeep_times );
717                                add_to_tree($curdeep_times, $name,
718                                            $t - $dprof_t - $overhead)
719                                  if $opt_S;
720                        }
721                }
722        }
723        if (defined $opt_g) {
724          $runtime = $ctimes->{$opt_g}/$hz;
725          $runtime = 0 unless $runtime > 0;
726        }
727}
728
729sub exitstamp {
730        my($stack, $tstack, $t, $times, $ctimes, $name, $in, $tab, $deep) = @_;
731        my( $x, $c, $z );
732
733        $x = pop( @$stack );
734        if( ! defined $x ){
735                die "Garbled profile, missing an enter time stamp";
736        }
737        if( $x->[0] ne $name ){
738          if ($x->[0] =~ /::AUTOLOAD$/) {
739            if ($opt_A) {
740              $name = $x->[0];
741            }
742          } elsif ( $opt_F ) {
743            warn( "Garbled profile, faking exit timestamp:\n\t$name => $x->[0].\n");
744            $name = $x->[0];
745          } else {
746            foreach $z (@stack, $x) {
747              print $z->[0],"\n";
748            }
749            die "Garbled profile, unexpected exit time stamp";
750          }
751        }
752        if( $opt_T || $opt_t ){
753                $$in -= $tab;
754        }
755        # collect childtime
756        $c = pop( @$tstack );
757        # total time this func has been active
758        $z = $t - $x->[1];
759        $ctimes->{$name} += $z;
760        $times->{$name} += ($z > $c)? $z - $c: 0;
761        # pass my time to my parent
762        if( @$tstack ){
763                $c = pop( @$tstack );
764                push( @$tstack, $c + $z );
765        }
766}
767
768
769sub header {
770        my $fh = shift;
771        chop($_ = <$fh>);
772        if( ! /^#fOrTyTwO$/ ){
773                die "Not a perl profile";
774        }
775        while(<$fh>){
776                next if /^#/;
777                last if /^PART/;
778                eval;
779        }
780        $over_tests = 1 unless $over_tests;
781        $time_precision = length int ($hz - 1); # log ;-)
782}
783
784
785# Report avg time-per-function in seconds
786sub percalc {
787        my( $calls, $times, $persecs, $idkeys ) = @_;
788        my( $x, $t, $n, $key );
789
790        for( $x = 0; $x < @$idkeys; ++$x ){
791                $key = $idkeys->[$x];
792                $n = $calls->{$key};
793                $t = $times->{$key} / $hz;
794                $persecs->{$key} = $t ? $t / $n : 0;
795        }
796}
797
798
799# Runs the given script with the given profiler and the given perl.
800sub run_profiler {
801        my $script = shift;
802        my $profiler = shift;
803        my $startperl = shift;
804
805        system $startperl, "-d:$profiler", $script;
806        if( $? / 256 > 0 ){
807                die "Failed: $startperl -d:$profiler $script: $!";
808        }
809}
810
811
812sub by_time { $times->{$b} <=> $times->{$a} }
813sub by_ctime { $ctimes->{$b} <=> $ctimes->{$a} }
814sub by_calls { $calls->{$b} <=> $calls->{$a} }
815sub by_alpha { $names->{$a} cmp $names->{$b} }
816sub by_avgcpu { $persecs->{$b} <=> $persecs->{$a} }
817
818
819format CSTAT_top =
820Total Elapsed Time = @>>>>>>> Seconds
821(($rrun_rtime - $overhead - $over_rtime * $total_marks/$over_tests/2) / $hz)
822  @>>>>>>>>>> Time = @>>>>>>> Seconds
823$whichtime, $runtime
824@<<<<<<<< Times
825$incl_excl
826%Time ExclSec CumulS #Calls sec/call Csec/c  Name
827.
828
829format STAT =
830 ^>>>   ^>>>> ^>>>>> ^>>>>>   ^>>>>> ^>>>>>  ^<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
831$pcnt, $secs, $csecs, $ncalls, $percall, $cpercall, $name
832.
833
834!NO!SUBS!
835
836close OUT or die "Can't close $file: $!";
837chmod 0755, $file or die "Can't reset permissions for $file: $!\n";
838exec("$Config{'eunicefix'} $file") if $Config{'eunicefix'} ne ':';
Note: See TracBrowser for help on using the repository browser.