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