commands/profile/sprofalyze.pl

   1 #!/usr/local/bin/perl
   2 #
   3 # sprofalyze.pl
   4 #
   5 # Analyzes the output files created by the profile command for
   6 # Statistical Profiling.
   7 #
   8 # Changes:
   9 #   14 Aug, 2006  Created (Rogier Meurs)
  10 #
  11
  12 # Configuration options:
  13
  14 # Location and parameters of nm program to extract symbol tables
  15 $nm = "/usr/bin/nm -dn";
  16
  17 # Location of src (including trailing /)
  18         $src_root = qw(
  19 /usr/src/
  20         );
  21
  22 # Location of system executables within src. Add new servers/drivers here.
  23 # This should be replaced with something less maintenance-prone some day.
  24         @exes = qw(
  25 kernel/kernel
  26
  27 servers/ds/ds
  28 servers/hgfs/hgfs
  29 servers/inet/inet
  30 servers/ipc/ipc
  31 servers/is/is
  32 servers/iso9660fs/isofs
  33 servers/mfs/mfs
  34 servers/pfs/pfs
  35 servers/pm/pm
  36 servers/rs/rs
  37 servers/vfs/vfs
  38 servers/vm/vm
  39 servers/rs/service
  40
  41 drivers/amddev/amddev
  42 drivers/at_wini/at_wini
  43 drivers/atl2/atl2
  44 drivers/audio/es1370/es1370
  45 drivers/audio/es1371/es1371
  46 drivers/bios_wini/bios_wini
  47 drivers/dec21140A/dec21140A
  48 drivers/dp8390/dp8390
  49 drivers/dpeth/dpeth
  50 drivers/e1000/e1000
  51 drivers/filter/filter
  52 drivers/floppy/floppy
  53 drivers/fxp/fxp
  54 drivers/lance/lance
  55 drivers/log/log
  56 drivers/memory/memory
  57 drivers/orinoco/orinoco
  58 drivers/pci/pci
  59 drivers/printer/printer
  60 drivers/random/random
  61 drivers/rtl8139/rtl8139
  62 drivers/rtl8169/rtl8169
  63 drivers/sb16/sb16_dsp
  64 drivers/sb16/sb16_mixer
  65 drivers/ti1225/ti1225
  66 drivers/tty/tty
  67         );
  68
  69 # 8< ----------- no user configurable parameters below this line ----------- >8
  70
  71 $SAMPLE_SIZE = 12;
  72 $MINIMUM_PERC = 1.0;
  73
  74
  75 if ($#ARGV < 0 || process_args(@ARGV)) {
  76   print "Usage:\n";
  77   print "  sprofalyze.pl [-p percentage] file ...\n\n";
  78   print "    percentage  print only processes/functions >= percentage\n";
  79   exit 1;
  80 }
  81
  82 sub process_args {
  83   $_ = shift;
  84
  85   if (/^-p$/) {
  86         $_ = shift;
  87         return 1 unless /^(\d{1,2})(.\d+)?$/;
  88         $MINIMUM_PERC = $1 + $2;
  89   } else {
  90         unshift @_, $_;
  91   }
  92
  93   @files = @_;
  94
  95   return 1 unless @files > 0;
  96
  97   return 0;
  98 }
  99
 100 if (read_symbols()) { exit 1; }
 101
 102 print "Showing processes and functions using at least $MINIMUM_PERC% time.\n";
 103
 104 foreach $file (@files) {
 105   if (process_datafile($file)) { exit 1; }
 106 }
 107
 108 exit 0;
 109
 110
 111 sub short_name
 112 {
 113   my $shortname = shift;
 114   $shortname =~ s/^.*\///;
 115   return substr($shortname, 0, 7);
 116 }
 117
 118
 119 sub read_symbols
 120 {
 121   print "Building indexes from symbol tables:";
 122
 123   for ($i=0; $i<= $#exes; $i++) {
 124         my $exe = @exes[$i];
 125         $shortname = $exe;
 126         $shortname =~ s/^.*\///;
 127         print " " if $i <= $#exes;
 128         print $shortname;
 129         $shortname = short_name($exe);
 130
 131         $fullname = $src_root . $exe;
 132
 133         if ((! -x $fullname) || (! -r $fullname)) {
 134                 print "\nERROR: $fullname does not exist or not readable.\n";
 135                 print "Did you do a make?\n";
 136                 return 1;
 137         }
 138
 139         # Create a hash entry for each symbol table (text) entry.
 140         foreach $_ (`$nm $fullname`) {
 141                 if (/^0{0,7}(\d{0,8})\s[tT]\s(\w{1,8})\n$/) {
 142                         ${$shortname."_hash"}{$1} = $2;
 143                 }
 144         }
 145
 146         # Create hash entries for every possible pc value. This will pay off.
 147         @lines = sort { $a <=> $b } keys %{$shortname."_hash"};
 148
 149         for ($y = 0; $y <= $#lines; $y++) {
 150                 for ($z = @lines->[$y] + 1; $z < @lines->[$y + 1]; $z++) {
 151                         ${$shortname."_hash"}{$z} =
 152                                 ${$shortname."_hash"}{@lines->[$y]}
 153                 }
 154         }
 155   }
 156
 157   # Clock and system are in kernel image but are seperate processes.
 158   push(@exes, "clock");
 159   push(@exes, "system");
 160   %clock_hash = %kernel_hash;
 161   %system_hash = %kernel_hash;
 162
 163   print ".\n\n";
 164   return 0;
 165 }
 166
 167
 168 sub process_datafile
 169 {
 170   my %res = ();
 171   my %merged = ();
 172   my $file = shift;
 173   my $buf, $pc, $exe, $total_system_perc;
 174
 175   unless (open(FILE, $file)) {
 176         print "\nERROR: Unable to open $file: $!\n";
 177         return 0;
 178   }
 179
 180   # First line: check file type.
 181   $_ = <FILE>; chomp;
 182   if (!/^stat$/) {
 183         if (/^call$/) {
 184                 print "Call Profiling output file: ";
 185                 print "Use cprofalyze.pl instead.\n";
 186         } else {
 187                 print "Not a profiling output file.\n";
 188         }
 189         return 0;
 190   }
 191
 192   $file =~ s/^.*\///;
 193
 194   printf "\n========================================";
 195   printf "========================================\n";
 196   printf("Data file: %s\n", $file);
 197   printf "========================================";
 198   printf "========================================\n\n";
 199
 200   # Read header with total, idle, system and user hits.
 201   $_ = <FILE>;
 202   chomp;
 203
 204   ($total_hits, $idle_hits, $system_hits, $user_hits) = split (/ /);
 205
 206   my $system_perc       = sprintf("%3.f", $system_hits / $total_hits * 100);
 207   my $user_perc         = sprintf("%3.f", $user_hits / $total_hits * 100);
 208   my $idle_perc         = 100 - $system_perc - $user_perc;
 209
 210   printf("  System process ticks: %10d (%3d%%)\n", $system_hits, $system_perc);
 211   printf("    User process ticks: %10d (%3d%%)", $user_hits, $user_perc);
 212   printf("          Details of system process\n");
 213   printf("       Idle time ticks: %10d (%3d%%)", $idle_hits, $idle_perc);
 214   printf("          samples, aggregated and\n");
 215   printf("                        ----------  ----");
 216   printf("           per process, are below.\n");
 217   printf("           Total ticks: %10d (100%)\n\n", $total_hits);
 218
 219   # Read sample records from file and increase relevant counters.
 220   until (eof(FILE)) {
 221         read(FILE, $buf, $SAMPLE_SIZE) == $SAMPLE_SIZE  or die ("Short read.");
 222         ($exe, $pc) = unpack("Z8i", $buf);
 223
 224         # We can access the hash by pc because they are all in there.
 225         if (!defined(${$exe."_hash"}{$pc})) {
 226                 print "ERROR: Undefined in symbol table indexes: ";
 227                 print "executable $exe  address $pc\n";
 228                 print "Did you include this executable in the configuration?\n";
 229                 return 1;
 230         }
 231         $res{$exe}{${$exe."_hash"}{$pc}} ++;
 232   }
 233
 234   # We only need to continue with executables that had any hits.
 235   my @actives = ();
 236   foreach my $exe (@exes) {
 237         $exe = short_name($exe);
 238         next if (!exists($res{$exe}));
 239         push(@actives, $exe);
 240   }
 241
 242   # Calculate number of samples for each executable and create aggregated hash.
 243   %exe_hits = ();
 244   foreach $exe (@actives) {
 245         foreach my $hits (values %{$res{$exe}}) {
 246                 $exe_hits{$exe} += $hits;
 247         }
 248
 249         foreach my $key (keys %{$res{$exe}}) {
 250                 $merged{sprintf("%8s %8s", $exe, $key)} = $res{$exe}{$key};
 251         }
 252   }
 253
 254   $total_system_perc = 0;
 255   # Print the aggregated results.
 256   process_hash("", \%merged);
 257
 258   # Print results for each executable in decreasing order.
 259   foreach my $exe
 260   (reverse sort { $exe_hits{$a} <=> $exe_hits{$b} } keys %exe_hits)
 261   {
 262         process_hash($exe, \%{$res{$exe}}) if
 263                 $exe_hits{$exe} >= $system_hits / 100 * $MINIMUM_PERC;
 264   }
 265
 266   # Print total of processes <threshold.
 267   printf "----------------------------------------";
 268   printf "----------------------------------------\n";
 269   printf("%-47s %5.1f%% of system process samples\n",
 270         "processes <$MINIMUM_PERC% (not showing functions)",
 271         100 - $total_system_perc);
 272   printf "----------------------------------------";
 273   printf "----------------------------------------\n";
 274   printf("%-47s 100.0%%\n\n", "total");
 275
 276   close(FILE);
 277   return 0;
 278 }
 279
 280
 281 sub process_hash
 282 {
 283   my $exe = shift;
 284   my $ref = shift;
 285   %hash = %{$ref};
 286   my $aggr = $exe eq "";
 287
 288   # Print a header.
 289   printf "----------------------------------------";
 290   printf "----------------------------------------\n";
 291   if ($aggr) {
 292         $astr_max = 55;
 293         $perc_hits = $system_hits / 100;
 294         printf("Total system process time %46d samples\n", $system_hits);
 295   } else {
 296         $astr_max = 64;
 297         $perc_hits = $exe_hits{$exe} / 100;
 298         $total_system_perc += $exe_perc =
 299                 sprintf("%5.1f", $exe_hits{$exe} / $system_hits * 100);
 300         printf("%-47s %5.1f%% of system process samples\n", $exe, $exe_perc);
 301   }
 302   printf "----------------------------------------";
 303   printf "----------------------------------------\n";
 304
 305
 306   # Delete functions <threshold.  Get percentage for all functions >threshold.
 307   my $below_thres_hits;
 308   my $total_exe_perc;
 309   foreach my $func (keys %hash)
 310   {
 311         if ($hash{$func} < $perc_hits * $MINIMUM_PERC) {
 312                 $below_thres_hits += $hash{$func};
 313                 delete($hash{$func});
 314         } else {
 315                 $total_exe_perc += sprintf("%3.1f", $hash{$func} / $perc_hits);
 316         }
 317   }
 318
 319   # Now print the hash entries in decreasing order.
 320   @sorted = reverse sort { $hash{$a} <=> $hash{$b} } keys %hash;
 321
 322   $astr_hits = ($hash{@sorted->[0]} > $below_thres_hits ?
 323         $hash{@sorted->[0]} : $below_thres_hits) / $astr_max;
 324
 325   foreach $func (@sorted) {
 326         process_line($func, $hash{$func});
 327   }
 328
 329   # Print <threshold hits.
 330   my $below_thres;
 331   if ($aggr) { $below_thres = "         "; }
 332   $below_thres .= sprintf("%8s", "<" . $MINIMUM_PERC . "%");
 333   process_line($below_thres, $below_thres_hits, 100 - $total_exe_perc);
 334
 335   # Print footer.
 336   printf "----------------------------------------";
 337   printf "----------------------------------------\n";
 338   printf("%-73s 100.0%%\n\n", $aggr ? "total" : $exe);
 339 }
 340
 341
 342 sub process_line
 343 {
 344   my $func = shift;
 345   my $hits = shift;
 346
 347   my $perc = $hits / $perc_hits;
 348   my $astr = $hits / $astr_hits;
 349
 350   if ($aggr) {
 351         print "$func ";
 352   } else {
 353         printf("%8s ", $func);
 354   }
 355   for ($i = 0; $i < $astr_max; $i++) {
 356         if ($i <= $astr) {
 357                 print "*";
 358         } else {
 359                 print " ";
 360         }
 361   }
 362   print " ";
 363   if (my $rest = shift) {
 364         printf("%5.1f%%\n", $rest);
 365   } else {
 366         printf("%5.1f%%\n", $perc);
 367   }
 368 }
 369