commands/profile/cprofalyze.pl

   1 #!/usr/pkg/bin/perl
   2 #
   3 # cprofalyze.pl
   4 #
   5 # Analyzes the output files created by the profile command for
   6 # Call Profiling.
   7 #
   8 # Changes:
   9 #   14 Aug, 2006  Created (Rogier Meurs)
  10 #
  11
  12 $UNSIGNED_MAX_DIV_K = 2**32/1000;
  13
  14
  15 if ($#ARGV == 0 || process_args(@ARGV)) {
  16         print "Usage:\n";
  17         print "  cprofalyze.pl <clock> [-f] [-aoct] [-i] [-n number] file ...\n\n";
  18         print "      clock  CPU clock of source machine in MHz (mandatory)\n";
  19         print "         -f  print totals per function (original order lost)\n";
  20         print "         -a  sort alphabetically (default)\n";
  21         print "         -o  no sort (original order)\n";
  22         print "         -c  sort by number of calls\n";
  23         print "         -t  sort by time spent\n";
  24         print "         -n  print maximum of number lines per process\n";
  25         print "         -i  when -[ao] used: print full paths\n";
  26         exit 1;
  27 }
  28
  29
  30 sub process_args {
  31   $_ = shift;
  32
  33   return 1 unless /^(\d+)$/;
  34   return 1 if $1 == 0;
  35   $MHz = $1;
  36
  37   $sort_method = "A";
  38   while (@_[0] =~ /^-/) {
  39         $_ = shift;
  40         SWITCH: {
  41                 if (/^-a$/) { $sort_method = "A"; last SWITCH; }
  42                 if (/^-o$/) { $sort_method = "O"; last SWITCH; }
  43                 if (/^-c$/) { $sort_method = "C"; last SWITCH; }
  44                 if (/^-t$/) { $sort_method = "T"; last SWITCH; }
  45                 if (/^-i$/) { $print_full_paths = 1; last SWITCH; }
  46                 if (/^-f$/) { $print_totals = 1; last SWITCH; }
  47                 if (/^-n$/) {
  48                         $_ = shift;
  49                         return 1 unless /^(\d+)$/;
  50                         return 1 unless $1 > 0;
  51                         $show_paths = $1;
  52                         last SWITCH;
  53                 }
  54                 return 1;
  55         }
  56   }
  57
  58   $print_full_paths == 1 && ($sort_method eq "T" || $sort_method eq "C") &&
  59   { $print_full_paths = 0 };
  60
  61   @files = @_;
  62   return 0;
  63 }
  64
  65
  66 print <<EOF;
  67 Notes:
  68 - Calls attributed to a path are calls done on that call level.
  69     For instance: a() is called once and calls b() twice. Call path "a" is
  70     attributed 1 call, call path "a b" is attributed 2 calls.
  71 - Time spent blocking is included.
  72 - Time attributed to a path is time spent on that call level.
  73     For instance: a() spends 10 cycles in its own body and calls b() which
  74     spends 5 cycles in its body. Call path "a" is attributed 10 cycles,
  75     call path "a b" is attributed 5 cycles.
  76 - Time is attributed when a function exits. Functions calls that have not
  77   returned yet are therefore not measured. This is most notable in main
  78   functions that are printed as having zero cycles.
  79 - When "profile reset" was run, the actual resetting in a process happens
  80   when a function is entered. In some processes (for example, blocking
  81   ones) this may not happen immediately, or at all.
  82
  83 EOF
  84
  85 print "Clockspeed entered: $MHz MHz. ";
  86 SWITCH: {
  87         if ($sort_method eq "A")
  88                 { print "Sorting alphabetically. "; last SWITCH; }
  89         if ($sort_method eq "C")
  90                 { print "Sorting by calls. "; last SWITCH; }
  91         if ($sort_method eq "T")
  92                 { print "Sorting by time spent. "; last SWITCH; }
  93         print "No sorting applied. ";
  94 }
  95 print "\n";
  96 $print_totals and print "Printing totals per function. ";
  97 $show_paths == 0 ? print "Printing all call paths.\n" :
  98         print "Printing max. $show_paths lines per process.\n";
  99
 100 foreach $file (@files) {
 101   $file_res = read_file($file);
 102   next if $file_res == 0;
 103   print_file($print_totals ? make_totals($file_res) : $file_res);
 104 }
 105
 106 exit 0;
 107
 108
 109 sub read_file
 110 {
 111   $file = shift;
 112   my %file_res = ();
 113   my @exe;
 114   my $exe_name, $slots_used, $buf, $lo, $hi, $cycles_div_k, $ms;
 115
 116   unless (open(FILE, $file)) {
 117         print "\nERROR: Unable to open $file: $!\n";
 118         return 0;
 119   }
 120
 121   $file =~ s/^.*\///;   # basename
 122
 123   # First line: check file type.
 124   $_ = <FILE>; chomp;
 125   if (!/^call$/) {
 126         if (/^stat$/) {
 127                 print "Statistical Profiling output file: ";
 128                 print "Use sprofalyze.pl instead.\n";
 129         } else {
 130                 print "Not a profiling output file.\n";
 131         }
 132         return 0;
 133   }
 134
 135   # Second line: header with call path string size.
 136   $_ = <FILE>; chomp;
 137   ($CPATH_MAX_LEN, $PROCNAME_LEN) = split(/ /);
 138   $SLOT_SIZE            = $CPATH_MAX_LEN + 16;
 139   $EXE_HEADER_SIZE      = $PROCNAME_LEN + 4;
 140
 141   # Read in the data for all the processes and put it in a hash of lists.
 142   # A list for each process, which contains lists itself for each call
 143   # path.
 144   until(eof(FILE)) {
 145         read(FILE, $buf, $EXE_HEADER_SIZE) == $EXE_HEADER_SIZE or
 146                                                         die ("Short read.");
 147         ($exe_name, $slots_used) = unpack("Z${PROCNAME_LEN}i", $buf);
 148
 149         @exe = ();
 150         for ($i=0; $i<$slots_used; $i++) {
 151                 read(FILE, $buf, $SLOT_SIZE) == $SLOT_SIZE or
 152                                                         die ("Short read.");
 153                 ($chain, $cpath, $calls, $lo, $hi) =
 154                         unpack("iA${CPATH_MAX_LEN}iII", $buf);
 155
 156                 $cycles_div_k = $hi * $UNSIGNED_MAX_DIV_K;
 157                 $cycles_div_k += $lo / 1000;
 158                 $ms = $cycles_div_k / $MHz;
 159
 160                 push @exe, [ ($cpath, $calls, $ms) ];
 161         }
 162         $file_res{$exe_name} = [ @exe ];
 163   }
 164   return \%file_res;
 165 }
 166
 167
 168 # Aggregate calls and cycles of paths into totals for each function.
 169 sub make_totals
 170 {
 171   my $ref = shift;
 172   my %file_res = %{$ref};
 173   my $exe;
 174   my %res, %calls, %time;
 175   my @totals;
 176
 177   foreach $exe (sort keys %file_res) {
 178         @totals = ();
 179         %calls = ();
 180         %time = ();
 181         @ar = @{$file_res{$exe}};
 182         foreach $path (@ar) {
 183                 $_ = $path->[0];
 184                 s/^.* //;       # basename of call path
 185                 $calls{$_}      += $path->[1];
 186                 $time{$_}       += $path->[2];
 187         }
 188         foreach $func (keys %calls) {
 189                 push @totals, [ ($func, $calls{$func}, $time{$func}) ];
 190         }
 191         $res{$exe} = [ @totals ];
 192   }
 193   return \%res;
 194 }
 195
 196
 197 sub print_file
 198 {
 199   my $ref = shift;
 200   my %file_res = %{$ref};
 201   my $exe;
 202
 203   printf "\n========================================";
 204   printf "========================================\n";
 205   printf("Data file: %s\n", $file);
 206   printf "========================================";
 207   printf "========================================\n\n";
 208
 209   # If we have the kernel, print it first. Then the others.
 210   print_exe($file_res{"kernel"}, "kernel") if exists($file_res{"kernel"});
 211
 212   foreach $exe (sort keys %file_res) {
 213         print_exe($file_res{$exe}, $exe) unless $exe eq "kernel";
 214   }
 215 }
 216
 217
 218 sub print_exe
 219 {
 220   my $ref = shift;
 221   my $name = shift;
 222   my @exe = @{$ref};
 223   my @funcs, @oldfuncs;
 224
 225   my $slots_used = @exe;
 226
 227   # Print a header.
 228   printf "----------------------------------------";
 229   printf "----------------------------------------\n";
 230   $print_totals ? printf "%-8s  %60s functions\n", $name, $slots_used :
 231                         printf "%-8s  %59s call paths\n", $name, $slots_used;
 232   printf "----------------------------------------";
 233   printf "----------------------------------------\n";
 234   printf("%10s  %12s  path\n", "calls", "msecs");
 235   printf "----------------------------------------";
 236   printf "----------------------------------------\n";
 237
 238   SWITCH: {
 239         if ($sort_method eq "A") {
 240                 @exe = sort { lc($a->[0]) cmp lc($b->[0]) } @exe; last SWITCH; }
 241         if ($sort_method eq "C") {
 242                 @exe = reverse sort { $a->[1] <=> $b->[1] } @exe; last SWITCH; }
 243         if ($sort_method eq "T") {
 244                 @exe = reverse sort { $a->[2] <=> $b->[2] } @exe; last SWITCH; }
 245         last SWITCH;
 246   }
 247
 248   my $paths;
 249   @oldfuncs = ();
 250   foreach $path (@exe) {
 251         printf("%10u  %12.2f  ", $path->[1], $path->[2]);
 252
 253         if ($print_full_paths == 1 ||
 254                 ($sort_method eq "C" || $sort_method eq "T")) {
 255                 print $path->[0];
 256         } else {
 257                 @funcs = split(/ /, $path->[0]);
 258                 for (my $j=0; $j<=$#funcs; $j++) {
 259                         if ($j<=$#oldfuncs && $funcs[$j] eq $oldfuncs[$j]) {
 260                                 print " ---";
 261                         } else {
 262                                 print " " if ($j > 0);
 263                                 print $funcs[$j];
 264                         }
 265                 }
 266                 @oldfuncs = @funcs;
 267         }
 268         print "\n";
 269         last if (++$paths == $show_paths);
 270   }
 271   print "\n";
 272 }
 273