X-Git-Url: https://perl5.git.perl.org/perl5.git/blobdiff_plain/19dda98f3cf253c51bb70f7b49299ce7b14e64d5..79c22d7eb145bcc6204dbf3411cd3b5d2ec706fe:/utils/dprofpp.PL diff --git a/utils/dprofpp.PL b/utils/dprofpp.PL index 1ef0b19..f9c487e 100644 --- a/utils/dprofpp.PL +++ b/utils/dprofpp.PL @@ -2,6 +2,7 @@ use Config; use File::Basename qw(&basename &dirname); +use File::Spec; # List explicitly here the variables you want Configure to # generate. Metaconfig only looks for shell variables, so you @@ -13,11 +14,10 @@ use File::Basename qw(&basename &dirname); # This forces PL files to create target in same directory as PL file. # This is so that make depend always knows where to find PL derivatives. chdir(dirname($0)); -($file = basename($0)) =~ s/\.PL$//; -$file =~ s/\.pl$// if ($Config{'osname'} eq 'OS2'); # "case-forgiving" -$file =~ s/\.pl$/.com/ if ($Config{'osname'} eq 'VMS'); # "case-forgiving" +($file = basename($0)) =~ s/\.PL$//i; +$file .= '.COM' if ($^O eq 'VMS'); -my $dprof_pm = '../ext/Devel/DProf/DProf.pm'; +my $dprof_pm = File::Spec->catfile(File::Spec->updir, 'ext', 'Devel', 'DProf', 'DProf.pm'); my $VERSION = 0; open( PM, "<$dprof_pm" ) || die "Can't open $dprof_pm: $!"; while(){ @@ -30,6 +30,13 @@ close PM; if( $VERSION == 0 ){ die "Did not find VERSION in $dprof_pm"; } +my $stty = 'undef'; +foreach my $s (qw(/bin/stty /usr/bin/stty)) { + if (-x $s) { + $stty = qq["$s"]; + last; + } +} open OUT,">$file" or die "Can't create $file: $!"; print "Extracting $file (with variable substitutions)\n"; @@ -45,6 +52,7 @@ $Config{'startperl'} require 5.003; my \$VERSION = '$VERSION'; +my \$stty = $stty; !GROK!THIS! @@ -73,13 +81,12 @@ dprofpp B<-V> [profile] The I command interprets profile data produced by a profiler, such as the Devel::DProf profiler. Dprofpp will read the file F and -will display the 15 subroutines which are using the most time. By default +display the 15 subroutines which are using the most time. By default the times for each subroutine are given exclusive of the times of their child subroutines. To profile a Perl script run the perl interpreter with the B<-d> switch. So -to profile script F with Devel::DProf the following command should -be used. +to profile script F with Devel::DProf use the following: $ perl5 -d:DProf test.pl @@ -227,7 +234,7 @@ calling level then it is displayed once with a repeat count. =item B<-S> -Display I subroutine call tree to stdout. Statistics is +Display I subroutine call tree to stdout. Statistics are displayed for each branch of the tree. When a function is called multiple (I) @@ -235,7 +242,7 @@ times in the same branch then all these calls go into one branch of the next level. A repeat count is output together with combined inclusive, exclusive and kids time. -Branches are sorted w.r.t. inclusive time. +Branches are sorted with regard to inclusive time. =item B<-U> @@ -277,12 +284,20 @@ or to group subroutines by name: =item B<-P> -Used with -G to aggregate "Pull" together all calls that did not match -G. +Used with -G to aggregate "Pull" together all calls that did not match -G. =item B<-f> Filter all calls matching the pattern. +=item B<-h> + +Display brief help and exit. + +=item B<-H> + +Display long help and exit. + =back =head1 ENVIRONMENT @@ -318,11 +333,46 @@ L, L, times(2) =cut +sub shortusage { + print <<'EOF'; +dprofpp [options] [profile] + + -A Count autoloaded to *AUTOLOAD + -a Sort by alphabetic name of subroutines. + -d Reverse sort + -E Sub times are reported exclusive of child times. (default) + -f Filter all calls mathcing the pattern. + -G Group all calls matching the pattern together. + -g subr Count only those who are SUBR or called from SUBR + -H Display long manual page. + -h Display this short usage message. + -I Sub times are reported inclusive of child times. + -l Sort by number of calls to subroutines. + -O cnt Specifies maximum number of subroutines to display. + -P Used with -G to pull all other calls together. + -p script Specifies name of script to be profiled. + -Q Used with -p to indicate the dprofpp should quit + after profiling the script, without interpreting the data. + -q Do not print column headers. + -R Count anonyms separately even if from the same package + -r Use real elapsed time rather than user+system time. + -S Create statistics for all the depths + -s Use system time rather than user+system time. + -T Show call tree. + -t Show call tree, compressed. + -U Do not sort subroutines. + -u Use user time rather than user+system time. + -V Print dprofpp's version. + -v Sort by average amount of time spent in subroutines. + -z Sort by user+system time spent in subroutines. (default) +EOF +} + use Getopt::Std 'getopts'; use Config '%Config'; Setup: { - my $options = 'O:g:G:Pf:dlzaAvuTtqrRsUFEIp:QVS'; + my $options = 'O:g:G:Pf:dlzaAvuTtqrRsUFEIp:QVShH'; $Monfile = 'tmon.out'; if( exists $ENV{DPROFPP_OPTS} ){ @@ -336,39 +386,21 @@ Setup: { @ARGV = @tmpargv; } - getopts( $options ); + getopts( $options ) or die "Try 'dprofpp -h' for help.\n"; if( @ARGV ){ # there was a filename, it overrides any earlier name. $Monfile = shift; } -# -O cnt Specifies maximum number of subroutines to display. -# -a Sort by alphabetic name of subroutines. -# -z Sort by user+system time spent in subroutines. (default) -# -l Sort by number of calls to subroutines. -# -v Sort by average amount of time spent in subroutines. -# -T Show call tree. -# -t Show call tree, compressed. -# -q Do not print column headers. -# -u Use user time rather than user+system time. -# -s Use system time rather than user+system time. -# -r Use real elapsed time rather than user+system time. -# -U Do not sort subroutines. -# -E Sub times are reported exclusive of child times. (default) -# -I Sub times are reported inclusive of child times. -# -V Print dprofpp's version. -# -p script Specifies name of script to be profiled. -# -Q Used with -p to indicate the dprofpp should quit after -# profiling the script, without interpreting the data. -# -A count autoloaded to *AUTOLOAD -# -R count anonyms separately even if from the same package -# -g subr count only those who are SUBR or called from SUBR -# -S Create statistics for all the depths - -# -G Group all calls matching the pattern together. -# -P Used with -G to pull all other calls together. -# -f Filter all calls mathcing the pattern. -# -d Reverse sort + if ( defined $opt_h ) { + shortusage(); + exit; + } + if ( defined $opt_H ) { + require Pod::Usage; + Pod::Usage::pod2usage( {-verbose => 2, -input => $0 } ); + exit; + } if( defined $opt_V ){ my $fh = 'main::fh'; @@ -534,16 +566,16 @@ sub settime { $hz ||= 1; if( $opt_r ){ - $$runtime = ($rrun_rtime - $overhead - $over_rtime * $total_marks/$over_tests/2)/$hz; + $$runtime = ($rrun_rtime - $overhead)/$hz; } elsif( $opt_s ){ - $$runtime = ($rrun_stime - $overhead - $over_stime * $total_marks/$over_tests/2)/$hz; + $$runtime = ($rrun_stime - $overhead)/$hz; } elsif( $opt_u ){ - $$runtime = ($rrun_utime - $overhead - $over_utime * $total_marks/$over_tests/2)/$hz; + $$runtime = ($rrun_utime - $overhead)/$hz; } else{ - $$runtime = ($rrun_ustime - $overhead - ($over_utime + $over_stime) * $total_marks/$over_tests/2)/$hz; + $$runtime = ($rrun_ustime - $overhead)/$hz; } $$runtime = 0 unless $$runtime > 0; } @@ -574,10 +606,9 @@ sub display_tree { exclusives_in_tree($deep_times); my $kid; - local *kids = $deep_times->{kids}; # %kids my $time; - if (%kids) { + if (%{$deep_times->{kids}}) { $time = sprintf '%.*fs = (%.*f + %.*f)', $time_precision, $deep_times->{incl_time}/$hz, $time_precision, $deep_times->{excl_time}/$hz, @@ -588,7 +619,7 @@ sub display_tree { print ' ' x (2*$level), "$name x $deep_times->{count} \t${time}s\n" if $deep_times->{count}; - for $kid (sort kids_by_incl keys %kids) { + for $kid (sort kids_by_incl %{$deep_times->{kids}}) { display_tree( $deep_times->{kids}{$kid}, $kid, $level + 1 ); } } @@ -625,15 +656,16 @@ sub display { sub move_keys { my ($source, $dest) = @_; - my $kid; - - for $kid (keys %$source) { - if (exists $dest->{$kid}) { - $dest->{count} += $source->{count}; - $dest->{incl_time} += $source->{incl_time}; - move_keys($source->{kids},$dest->{kids}); + + for my $kid_name (keys %$source) { + my $source_kid = delete $source->{$kid_name}; + + if (my $dest_kid = $dest->{$kid_name}) { + $dest_kid->{count} += $source_kid->{count}; + $dest_kid->{incl_time} += $source_kid->{incl_time}; + move_keys($source_kid->{kids},$dest_kid->{kids}); } else { - $dest->{$kid} = delete $source->{$kid}; + $dest->{$kid_name} = $source_kid; } } } @@ -644,11 +676,11 @@ sub add_to_tree { $name = $curdeep_times->[-1]{name}; } die "Shorted?!" unless @$curdeep_times >= 2; - $curdeep_times->[-2]{kids}{$name} = { count => 0 , kids => {}, - incl_time => 0, - } - unless exists $curdeep_times->[-2]{kids}{$name}; - my $entry = $curdeep_times->[-2]{kids}{$name}; + my $entry = $curdeep_times->[-2]{kids}{$name} ||= { + count => 0, + kids => {}, + incl_time => 0, + }; # Now transfer to the new node (could not do earlier, since name can change) $entry->{count}++; $entry->{incl_time} += $t - $curdeep_times->[-1]{enter_stamp}; @@ -665,6 +697,7 @@ sub parsestack { my( $x, $z, $c, $id, $pack ); my @stack = (); my @tstack = (); + my %outer; my $tab = 3; my $in = 0; @@ -673,7 +706,6 @@ sub parsestack { my $l_name = ''; my $repcnt = 0; my $repstr = ''; - my $dprof_t = 0; my $dprof_stamp; my %cv_hash; my $in_level = not defined $opt_g; # Level deep in report grouping @@ -703,7 +735,7 @@ sub parsestack { my $ot = $t; if ( $dir eq '/' ) { - $syst = $stack[-1][0]; + $syst = $stack[-1][0] if scalar @stack; $usert = '&'; $dir = '-'; #warn("Inserted exit for $stack[-1][0].\n") @@ -719,22 +751,22 @@ sub parsestack { $name = defined $syst ? $syst : $cv_hash{$usert}; } - next unless $in_level or $name eq $opt_g or $dir eq '*'; + next unless $in_level or $name eq $opt_g; if ( $dir eq '-' or $dir eq '*' ) { my $ename = $dir eq '*' ? $stack[-1][0] : $name; $overhead += $over_per_call; if ($name eq "Devel::DProf::write") { - $dprof_t += $t - $dprof_stamp; + $overhead += $t - $dprof_stamp; next; } elsif (defined $opt_g and $ename eq $opt_g) { $in_level--; } add_to_tree($curdeep_times, $ename, - $t - $dprof_t - $overhead) if $opt_S; - exitstamp( \@stack, \@tstack, - $t - $dprof_t - $overhead, - $times, $ctimes, $ename, \$in, $tab, - $curdeep_times ); + $t - $overhead) if $opt_S; + exitstamp( \@stack, \@tstack, + $t - $overhead, + $times, $ctimes, $name, \$in, $tab, + $curdeep_times, \%outer ); } next unless $in_level or $name eq $opt_g; if( $dir eq '+' or $dir eq '*' ){ @@ -773,11 +805,12 @@ sub parsestack { push( @$idkeys, $name ); } $calls->{$name}++; + $outer{$name}++; push @$curdeep_times, { kids => {}, name => $name, - enter_stamp => $t - $dprof_t - $overhead, + enter_stamp => $t - $overhead, } if $opt_S; - $x = [ $name, $t - $dprof_t - $overhead ]; + $x = [ $name, $t - $overhead ]; push( @stack, $x ); # my children will put their time here @@ -791,6 +824,11 @@ sub parsestack { print ' ' x $l_in, "$l_name$repstr\n"; } + while (my ($key, $count) = each %outer) { + next unless $count; + warn "$key has $count unstacked calls in outer\n"; + } + if( @stack ){ if( ! $opt_F ){ warn "Garbled profile is missing some exit time stamps:\n"; @@ -806,11 +844,11 @@ sub parsestack { foreach $x ( reverse @stack ){ $name = $x->[0]; exitstamp( \@stack, \@tstack, - $t - $dprof_t - $overhead, $times, + $t - $overhead, $times, $ctimes, $name, \$in, $tab, - $curdeep_times ); + $curdeep_times, \%outer ); add_to_tree($curdeep_times, $name, - $t - $dprof_t - $overhead) + $t - $overhead) if $opt_S; } } @@ -822,7 +860,7 @@ sub parsestack { } sub exitstamp { - my($stack, $tstack, $t, $times, $ctimes, $name, $in, $tab, $deep) = @_; + my($stack, $tstack, $t, $times, $ctimes, $name, $in, $tab, $deep, $outer) = @_; my( $x, $c, $z ); $x = pop( @$stack ); @@ -851,8 +889,9 @@ sub exitstamp { $c = pop( @$tstack ); # total time this func has been active $z = $t - $x->[1]; - $ctimes->{$name} += $z; - $times->{$name} += ($z > $c)? $z - $c: 0; + $ctimes->{$name} += $z + unless --$outer->{$name}; + $times->{$name} += $z - $c; # pass my time to my parent if( @$tstack ){ $c = pop( @$tstack ); @@ -921,7 +960,7 @@ sub rby_avgcpu { $persecs->{$a} <=> $persecs->{$b} } format CSTAT_top = Total Elapsed Time = @>>>>>>> Seconds -(($rrun_rtime - $overhead - $over_rtime * $total_marks/$over_tests/2) / $hz) +(($rrun_rtime - $overhead) / $hz) @>>>>>>>>>> Time = @>>>>>>> Seconds $whichtime, $runtime @<<<<<<<< Times @@ -929,11 +968,17 @@ $incl_excl %Time ExclSec CumulS #Calls sec/call Csec/c Name . -format STAT = - ^>>> ^>>>> ^>>>>> ^>>>>> ^>>>>> ^>>>>> ^<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< -$pcnt, $secs, $csecs, $ncalls, $percall, $cpercall, $name -. +BEGIN { + my $fmt = ' ^>>> ^>>>> ^>>>>> ^>>>>> ^>>>>> ^>>>>> ^<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<'; + if (-t STDOUT and defined $stty and my ($cols) = `$stty -a` =~ /\bcolumns\s+(\d+)/) + { + $fmt .= '<' x ($cols - length $fmt) if $cols > 80; + } + eval "format STAT = \n$fmt" . ' +$pcnt, $secs, $csecs, $ncalls, $percall, $cpercall, $name +.'; +} !NO!SUBS! close OUT or die "Can't close $file: $!";