Integrate changes #9511,9514,9517 from maintperl into mainline.
[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);
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$//;
c93fa817 17$file =~ s/\.pl$// if ($Config{'osname'} eq 'OS2'); # "case-forgiving"
18$file =~ s/\.pl$/.com/ if ($Config{'osname'} eq 'VMS'); # "case-forgiving"
583a019e 19
51e5ddcf 20my $dprof_pm = '../ext/Devel/DProf/DProf.pm';
583a019e 21my $VERSION = 0;
51e5ddcf 22open( PM, "<$dprof_pm" ) || die "Can't open $dprof_pm: $!";
23while(<PM>){
49771424 24 if( /^\$Devel::DProf::VERSION\s*=\s*'([\d._]+)'/ ){
583a019e 25 $VERSION = $1;
26 last;
27 }
28}
51e5ddcf 29close PM;
583a019e 30if( $VERSION == 0 ){
51e5ddcf 31 die "Did not find VERSION in $dprof_pm";
583a019e 32}
583a019e 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
49771424 47my \$VERSION = '$VERSION';
583a019e 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
6fb76034 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.
583a019e 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
6fb76034 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
583a019e 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 ) = @_;
93683c21 439
440 $hz ||= 1;
583a019e 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 ':';