diff --git a/commands/Makefile b/commands/Makefile index 6092e6a7f..722f5244b 100644 --- a/commands/Makefile +++ b/commands/Makefile @@ -25,7 +25,7 @@ SUBDIR= add_route arp ash at \ ramdisk rarpd rawspeed rcp rdate readall readclock \ reboot remsync rev rget rlogin \ rotate rsh rshd service setup shar acksize \ - sleep slip sort spell split srccrc \ + sleep slip sort spell split sprofalyze srccrc \ stty sum svclog svrctl swifi sync synctree sysenv \ syslogd tail tar tcpd tcpdp tcpstat tee telnet \ telnetd term termcap tget time touch tr \ diff --git a/commands/profile/Makefile b/commands/profile/Makefile index 2d6dc1df3..9a50dcb00 100644 --- a/commands/profile/Makefile +++ b/commands/profile/Makefile @@ -1,7 +1,7 @@ -# Makefile for profile and profalyze.pl +# Makefile for profile and cprofalyze.pl PROG= profile -SCRIPTS= sprofalyze.pl cprofalyze.pl +SCRIPTS= cprofalyze.pl MAN= .include diff --git a/commands/profile/sprofalyze.pl b/commands/profile/sprofalyze.pl deleted file mode 100755 index d4d9501a8..000000000 --- a/commands/profile/sprofalyze.pl +++ /dev/null @@ -1,378 +0,0 @@ -#!/usr/pkg/bin/perl -# -# sprofalyze.pl -# -# Analyzes the output files created by the profile command for -# Statistical Profiling. -# -# Changes: -# 14 Aug, 2006 Created (Rogier Meurs) -# - -# Configuration options: - -# Location and parameters of nm program to extract symbol tables -$nm = "/usr/pkg/bin/nm --radix=d -n"; - -# Location of src (including trailing /) - $src_root = qw( -/usr/src/ - ); - -# Location of system executables within src. Add new servers/drivers here. -# This should be replaced with something less maintenance-prone some day. - @exes = qw( -kernel/kernel - -servers/ds/ds -servers/hgfs/hgfs -servers/inet/inet -servers/ipc/ipc -servers/is/is -servers/iso9660fs/isofs -servers/mfs/mfs -servers/pfs/pfs -servers/pm/pm -servers/procfs/procfs -servers/rs/rs -servers/sched/sched -servers/vbfs/vbfs -servers/vfs/vfs -servers/vm/vm -servers/sched/sched -commands/service/service - -drivers/ahci/ahci -drivers/acpi/acpi -drivers/amddev/amddev -drivers/at_wini/at_wini -drivers/atl2/atl2 -drivers/audio/es1370/es1370 -drivers/audio/es1371/es1371 -drivers/dec21140A/dec21140A -drivers/dp8390/dp8390 -drivers/dpeth/dpeth -drivers/e1000/e1000 -drivers/fbd/fbd -drivers/filter/filter -drivers/floppy/floppy -drivers/fxp/fxp -drivers/lance/lance -drivers/log/log -drivers/memory/memory -drivers/orinoco/orinoco -drivers/pci/pci -drivers/printer/printer -drivers/random/random -drivers/rtl8139/rtl8139 -drivers/rtl8169/rtl8169 -drivers/ti1225/ti1225 -drivers/tty/tty -drivers/vbox/vbox - ); - -# 8< ----------- no user configurable parameters below this line ----------- >8 - -$SAMPLE_SIZE = 12; -$MINIMUM_PERC = 1.0; - - -if ($#ARGV < 0 || process_args(@ARGV)) { - print "Usage:\n"; - print " sprofalyze.pl [-p percentage] file ...\n\n"; - print " percentage print only processes/functions >= percentage\n"; - exit 1; -} - -sub process_args { - $_ = shift; - - if (/^-p$/) { - $_ = shift; - return 1 unless /^(\d{1,2})(.\d+)?$/; - $MINIMUM_PERC = $1 + $2; - } else { - unshift @_, $_; - } - - @files = @_; - - return 1 unless @files > 0; - - return 0; -} - -if (read_symbols()) { exit 1; } - -print "Showing processes and functions using at least $MINIMUM_PERC% time.\n"; - -foreach $file (@files) { - if (process_datafile($file)) { exit 1; } -} - -exit 0; - - -sub short_name -{ - my $shortname = shift; - $shortname =~ s/^.*\///; - return substr($shortname, 0, 7); -} - - -sub read_symbols -{ - print "Building indexes from symbol tables:"; - - for ($i=0; $i<= $#exes; $i++) { - my $exe = @exes[$i]; - $shortname = $exe; - $shortname =~ s/^.*\///; - print " " if $i <= $#exes; - print $shortname; - $shortname = short_name($exe); - - $fullname = $src_root . $exe; - - if ((! -x $fullname) || (! -r $fullname)) { - print "\nWARNING: $fullname does not exist or not readable.\n"; - print "Did you do a make?\n"; - next; - } - - # Create a hash entry for each symbol table (text) entry. - foreach $_ (`$nm $fullname`) { - if (/^0{0,7}(\d{0,10})\s[tT]\s(\w{1,32})\n$/) { - ${$shortname."_hash"}{$1} = $2; - } - } - - # Create hash entries for every possible pc value. This will pay off. - @lines = sort { $a <=> $b } keys %{$shortname."_hash"}; - - for ($y = 0; $y <= $#lines; $y++) { - for ($z = @lines->[$y] + 1; $z < @lines->[$y + 1]; $z++) { - ${$shortname."_hash"}{$z} = - ${$shortname."_hash"}{@lines->[$y]} - } - } - } - - # Clock and system are in kernel image but are seperate processes. - push(@exes, "clock"); - push(@exes, "system"); - %clock_hash = %kernel_hash; - %system_hash = %kernel_hash; - - print ".\n\n"; - return 0; -} - - -sub process_datafile -{ - my %res = (); - my %merged = (); - my $file = shift; - my $buf, $pc, $exe, $total_system_perc; - - unless (open(FILE, $file)) { - print "\nERROR: Unable to open $file: $!\n"; - return 0; - } - - # First line: check file type. - $_ = ; chomp; - if (!/^stat$/) { - if (/^call$/) { - print "Call Profiling output file: "; - print "Use cprofalyze.pl instead.\n"; - } else { - print "Not a profiling output file.\n"; - } - return 0; - } - - $file =~ s/^.*\///; - - printf "\n========================================"; - printf "========================================\n"; - printf("Data file: %s\n", $file); - printf "========================================"; - printf "========================================\n\n"; - - # Read header with total, idle, system and user hits. - $_ = ; - chomp; - - ($total_hits, $idle_hits, $system_hits, $user_hits) = split (/ /); - - my $system_perc = sprintf("%3.f", $system_hits / $total_hits * 100); - my $user_perc = sprintf("%3.f", $user_hits / $total_hits * 100); - my $idle_perc = 100 - $system_perc - $user_perc; - - printf(" System process ticks: %10d (%3d%%)\n", $system_hits, $system_perc); - printf(" User process ticks: %10d (%3d%%)", $user_hits, $user_perc); - printf(" Details of system process\n"); - printf(" Idle time ticks: %10d (%3d%%)", $idle_hits, $idle_perc); - printf(" samples, aggregated and\n"); - printf(" ---------- ----"); - printf(" per process, are below.\n"); - printf(" Total ticks: %10d (100%)\n\n", $total_hits); - - # Read sample records from file and increase relevant counters. - until (eof(FILE)) { - read(FILE, $buf, $SAMPLE_SIZE) == $SAMPLE_SIZE or die ("Short read."); - ($exe, $pc) = unpack("Z8i", $buf); - - # The kernel mangles process names for debugging purposes. - # We compensate for that here. - $exe =~ s/\*F$//; - - # We can access the hash by pc because they are all in there. - if (!defined(${$exe."_hash"}{$pc})) { - print "ERROR: Undefined in symbol table indexes: "; - print "executable $exe address $pc\n"; - print "Did you include this executable in the configuration?\n"; - return 1; - } - $res{$exe}{${$exe."_hash"}{$pc}} ++; - } - - # We only need to continue with executables that had any hits. - my @actives = (); - foreach my $exe (@exes) { - $exe = short_name($exe); - next if (!exists($res{$exe})); - push(@actives, $exe); - } - - # Calculate number of samples for each executable and create aggregated hash. - %exe_hits = (); - foreach $exe (@actives) { - foreach my $hits (values %{$res{$exe}}) { - $exe_hits{$exe} += $hits; - } - - foreach my $key (keys %{$res{$exe}}) { - $merged{sprintf("%8s %32s", $exe, $key)} = $res{$exe}{$key}; - } - } - - $total_system_perc = 0; - # Print the aggregated results. - process_hash("", \%merged); - - # Print results for each executable in decreasing order. - foreach my $exe - (reverse sort { $exe_hits{$a} <=> $exe_hits{$b} } keys %exe_hits) - { - process_hash($exe, \%{$res{$exe}}) if - $exe_hits{$exe} >= $system_hits / 100 * $MINIMUM_PERC; - } - - # Print total of processes threshold. - my $below_thres_hits; - my $total_exe_perc; - foreach my $func (keys %hash) - { - if ($hash{$func} < $perc_hits * $MINIMUM_PERC) { - $below_thres_hits += $hash{$func}; - delete($hash{$func}); - } else { - $total_exe_perc += sprintf("%3.1f", $hash{$func} / $perc_hits); - } - } - - # Now print the hash entries in decreasing order. - @sorted = reverse sort { $hash{$a} <=> $hash{$b} } keys %hash; - - $astr_hits = ($hash{@sorted->[0]} > $below_thres_hits ? - $hash{@sorted->[0]} : $below_thres_hits) / $astr_max; - - foreach $func (@sorted) { - process_line($func, $hash{$func}); - } - - # Print diff --git a/commands/sprofalyze/sprofalyze.c b/commands/sprofalyze/sprofalyze.c new file mode 100755 index 000000000..ad3125c90 --- /dev/null +++ b/commands/sprofalyze/sprofalyze.c @@ -0,0 +1,859 @@ +#include +#include +#include +#include +#include +#include +#include +#include + +/* user-configurable settings */ +#define BINARY_HASHTAB_SIZE 1024 + +#define DEBUG 0 + +#define NM "/usr/pkg/bin/nm" + +static const char *default_binaries[] = { + "kernel/kernel", + "servers/", + "drivers/", +}; + +static const char *src_path = "/usr/src"; + +/* types */ + +#define BINARY_NAME_SIZE 8 + +#define LINE_WIDTH 80 + +#define SYMBOL_NAME_SIZE 52 + +#define SYMBOL_NAME_WIDTH 22 + +#define SYMBOL_SIZE_MAX 0x100000 + +#define PC_MAP_L1_SIZE 0x10000 +#define PC_MAP_L2_SIZE 0x10000 + +struct binary_info; + +struct symbol_count { + struct symbol_count *next; + struct binary_info *binary; + uint32_t addr; + int samples; + char name[SYMBOL_NAME_SIZE]; +}; + +struct pc_map_l2 { + struct symbol_count *l2[PC_MAP_L2_SIZE]; +}; + +struct pc_map_l1 { + struct pc_map_l2 *l1[PC_MAP_L1_SIZE]; +}; + +struct binary_info { + char name[BINARY_NAME_SIZE]; + const char *path; + int samples; + struct symbol_count *symbols; + struct pc_map_l1 *pc_map; + struct binary_info *next; + struct binary_info *hashtab_next; + char no_more_warnings; +}; + +struct trace_sample { + char name[BINARY_NAME_SIZE]; + uint32_t pc; +}; + +/* global variables */ +static struct binary_info *binaries; +static struct binary_info *binary_hashtab[BINARY_HASHTAB_SIZE]; +static double minimum_perc = 1.0; +static int samples_idle, samples_system, samples_total, samples_user; + +/* prototypes */ +static struct binary_info *binary_add(const char *path); +static struct binary_info *binary_find(const char *name); +static struct binary_info *binary_hashtab_get(const char *name); +static struct binary_info **binary_hashtab_get_ptr(const char *name); +static void binary_load_pc_map(struct binary_info *binary_info); +static const char *binary_name(const char *path); +static int compare_binaries(const void *p1, const void *p2); +static int compare_symbols(const void *p1, const void *p2); +static int count_symbols(const struct binary_info *binary, int threshold); +static void load_trace(const char *path); +static void *malloc_checked(size_t size); +static unsigned name_hash(const char *name); +static float percent(int value, int percent_of); +static void print_report(void); +static void print_report_overall(void); +static void print_report_per_binary(const struct binary_info *binary); +static void print_reports_per_binary(void); +static void print_report_symbols(struct symbol_count **symbols, + unsigned symbol_count, int total, int show_binary); +static void print_separator(void); +static int read_hex(FILE *file, unsigned long *value); +static int read_newline(FILE *file); +static void read_nm_line(FILE *file, int line, char *name, char *type, + unsigned long *addr, unsigned long *size); +static void read_to_whitespace(FILE *file, char *buffer, size_t size); +static void sample_store(const struct trace_sample *sample); +static char *strdup_checked(const char *s); +static void usage(const char *argv0); + +#define MALLOC_CHECKED(type, count) \ + ((type *) malloc_checked(sizeof(type) * (count))) + +#define LENGTHOF(array) (sizeof((array)) / sizeof((array)[0])) + +#if DEBUG +#define dprintf(...) do { \ + fprintf(stderr, "debug(%s:%d): ", __FUNCTION__, __LINE__); \ + fprintf(stderr, __VA_ARGS__); \ +} while(0) +#else +#define dprintf(...) +#endif + +int main(int argc, char **argv) { + int opt; + +#ifdef DEBUG + /* disable buffering so the output mixes correctly */ + setvbuf(stdout, NULL, _IONBF, 0); + setvbuf(stderr, NULL, _IONBF, 0); +#endif + + /* parse arguments */ + while ((opt = getopt(argc, argv, "b:p:s:")) != -1) { + switch (opt) { + case 'b': + /* additional binary specified */ + binary_add(optarg); + break; + case 'p': + /* minimum percentage specified */ + minimum_perc = atof(optarg); + if (minimum_perc < 0 || minimum_perc > 100) { + fprintf(stderr, "error: cut-off percentage " + "makes no sense: %g\n", minimum_perc); + exit(1); + } + break; + case 's': + /* source tree directory specified */ + src_path = optarg; + break; + default: usage(argv[0]); + } + } + + /* load samples */ + if (optind >= argc) usage(argv[0]); + for (; optind < argc; optind++) { + load_trace(argv[optind]); + } + + /* print report */ + print_report(); + return 0; +} + +static struct binary_info *binary_add(const char *path) { + struct binary_info *binary, **ptr; + const char *name; + + /* assumption: path won't be overwritten or deallocated in the future */ + + /* not too much effort escaping for popen, prevent problems here */ + assert(path); + if (strchr(path, '"')) { + fprintf(stderr, "error: path \"%s\" contains a quote\n", path); + exit(1); + } + + /* get filename */ + name = binary_name(path); + dprintf("adding binary \"%s\" with name \"%.*s\"\n", + path, BINARY_NAME_SIZE, name); + if (strlen(name) == 0) { + fprintf(stderr, "error: path \"%s\" does not " + "contain a filename\n", path); + exit(1); + } + + /* check in hashtable whether this entry is indeed new */ + ptr = binary_hashtab_get_ptr(name); + if (*ptr) { + fprintf(stderr, "warning: ignoring \"%s\" because \"%s\" was " + "previously specified\n", path, (*ptr)->path); + return *ptr; + } + dprintf("using %.*s from \"%s\"\n", BINARY_NAME_SIZE, name, path); + + /* allocate new binary_info */ + binary = MALLOC_CHECKED(struct binary_info, 1); + memset(binary, 0, sizeof(struct binary_info)); + binary->path = path; + strncpy(binary->name, name, sizeof(binary->name)); + + /* insert into linked list */ + binary->next = binaries; + binaries = binary; + + /* insert into hashtable */ + *ptr = binary; + return binary; +} + +static struct binary_info *binary_find(const char *name) { + struct binary_info *binary; + const char *current_name; + unsigned i; + char path[PATH_MAX + 1], *path_end; + + assert(name); + + /* name is required */ + if (!*name) { + fprintf(stderr, "warning: binary unspecified in sample\n"); + return NULL; + } + + /* do we already know this binary? */ + binary = binary_hashtab_get(name); + if (binary) return binary; + + /* search for it */ + dprintf("searching for binary \"%.*s\" in \"%s\"\n", + BINARY_NAME_SIZE, name, src_path); + for (i = 0; i < LENGTHOF(default_binaries); i++) { + snprintf(path, sizeof(path), "%s/%s", src_path, + default_binaries[i]); + current_name = binary_name(path); + assert(current_name); + if (*current_name) { + /* paths not ending in slash: use if name matches */ + if (strncmp(name, current_name, + BINARY_NAME_SIZE) != 0) { + continue; + } + } else { + /* paths ending in slash: look in subdir named after + * binary + */ + path_end = path + strlen(path); + snprintf(path_end, sizeof(path) - (path_end - path), + "%.*s/%.*s", BINARY_NAME_SIZE, name, + BINARY_NAME_SIZE, name); + } + + /* use access to find out whether the binary exists and is + * readable + */ + dprintf("checking whether \"%s\" exists\n", path); + if (access(path, R_OK) < 0) continue; + + /* ok, this seems to be the one */ + return binary_add(strdup_checked(path)); + } + + /* not found */ + return NULL; +} + +static struct binary_info *binary_hashtab_get(const char *name) { + return *binary_hashtab_get_ptr(name); +} + +static struct binary_info **binary_hashtab_get_ptr(const char *name) { + struct binary_info *binary, **ptr; + + /* get pointer to location of the binary in hash table */ + ptr = &binary_hashtab[name_hash(name) % BINARY_HASHTAB_SIZE]; + while ((binary = *ptr) && strncmp(binary->name, name, + BINARY_NAME_SIZE) != 0) { + ptr = &binary->hashtab_next; + } + dprintf("looked up \"%.*s\" in hash table, %sfound\n", + BINARY_NAME_SIZE, name, *ptr ? "" : "not "); + return ptr; +} + +static void binary_load_pc_map(struct binary_info *binary_info) { + unsigned long addr, size; + char *command; + size_t command_len; +#if DEBUG + unsigned count = 0; +#endif + FILE *file; + int index_l1, index_l2, line; + char name[SYMBOL_NAME_SIZE]; + struct pc_map_l2 *pc_map_l2, **pc_map_l2_ptr; + struct symbol_count *symbol, **symbol_ptr; + char type; + + assert(binary_info); + assert(!strchr(NM, '"')); + assert(!strchr(binary_info->path, '"')); + + /* does the file exist? */ + if (access(binary_info->path, R_OK) < 0) { + if (!binary_info->no_more_warnings) { + fprintf(stderr, "warning: \"%s\" does not exist or " + "not readable.\n", binary_info->path); + fprintf(stderr, " Did you do a make?\n"); + binary_info->no_more_warnings = 1; + } + return; + } + + /* execute nm to get symbols */ + command_len = strlen(NM) + strlen(binary_info->path) + 32; + command = MALLOC_CHECKED(char, command_len); + snprintf(command, command_len, "\"%s\" -nP \"%s\"", + NM, binary_info->path); + dprintf("running command for extracting addresses: %s\n", command); + file = popen(command, "r"); + if (!file) { + perror("failed to start " NM); + exit(-1); + } + + /* read symbols from nm output */ + assert(!binary_info->symbols); + symbol_ptr = &binary_info->symbols; + line = 1; + while (!feof(file)) { + /* read nm output line; can't use fscanf as it doesn't know + * where to stop + */ + read_nm_line(file, line++, name, &type, &addr, &size); + + /* store only text symbols */ + if (type != 't' && type != 'T') continue; + + *symbol_ptr = symbol = MALLOC_CHECKED(struct symbol_count, 1); + memset(symbol, 0, sizeof(*symbol)); + symbol->binary = binary_info; + symbol->addr = addr; + strncpy(symbol->name, name, SYMBOL_NAME_SIZE); + symbol_ptr = &symbol->next; +#if DEBUG + count++; +#endif + } + fclose(file); + dprintf("extracted %u symbols\n", count); + + /* create program counter map from symbols */ + assert(!binary_info->pc_map); + binary_info->pc_map = MALLOC_CHECKED(struct pc_map_l1, 1); + memset(binary_info->pc_map, 0, sizeof(struct pc_map_l1)); + for (symbol = binary_info->symbols; symbol; symbol = symbol->next) { + /* compute size if not specified */ + size = symbol->next ? (symbol->next->addr - symbol->addr) : 1; + if (size > SYMBOL_SIZE_MAX) size = SYMBOL_SIZE_MAX; + + /* mark each address */ + for (addr = symbol->addr; addr - symbol->addr < size; addr++) { + index_l1 = addr / PC_MAP_L2_SIZE; + assert(index_l1 < PC_MAP_L1_SIZE); + pc_map_l2_ptr = &binary_info->pc_map->l1[index_l1]; + if (!(pc_map_l2 = *pc_map_l2_ptr)) { + *pc_map_l2_ptr = pc_map_l2 = + MALLOC_CHECKED(struct pc_map_l2, 1); + memset(pc_map_l2, 0, sizeof(struct pc_map_l2)); + } + index_l2 = addr % PC_MAP_L2_SIZE; + pc_map_l2->l2[index_l2] = symbol; + } + } +} + +static const char *binary_name(const char *path) { + const char *name, *p; + + /* much like basename, but guarantees to not modify the path */ + name = path; + for (p = path; *p; p++) { + if (*p == '/') name = p + 1; + } + return name; +} + +static int compare_binaries(const void *p1, const void *p2) { + const struct binary_info *const *b1 = p1, *const *b2 = p2; + + /* binaries with more samples come first */ + assert(b1); + assert(b2); + assert(*b1); + assert(*b2); + if ((*b1)->samples > (*b2)->samples) return -1; + if ((*b1)->samples < (*b2)->samples) return 1; + return 0; +} + +static int compare_symbols(const void *p1, const void *p2) { + const struct symbol_count *const *s1 = p1, *const *s2 = p2; + + /* symbols with more samples come first */ + assert(s1); + assert(s2); + assert(*s1); + assert(*s2); + if ((*s1)->samples > (*s2)->samples) return -1; + if ((*s1)->samples < (*s2)->samples) return 1; + return 0; +} + +static int count_symbols(const struct binary_info *binary, int threshold) { + struct symbol_count *symbol; + int result = 0; + + for (symbol = binary->symbols; symbol; symbol = symbol->next) { + if (symbol->samples >= threshold) result++; + } + return result; +} + +static void load_trace(const char *path) { + FILE *file; + int s_idle, s_system, s_total, s_user; + int samples_read; + struct trace_sample sample; + + /* open trace file */ + file = fopen(path, "rb"); + if (!file) { + fprintf(stderr, "error: cannot open trace file \"%s\": %s\n", + path, strerror(errno)); + exit(1); + } + + /* check file format and update totals */ + if (fscanf(file, "stat\n%d %d %d %d\n", + &s_total, &s_idle, &s_system, &s_user) != 4) { + fprintf(stderr, "error: file \"%s\" does not contain an " + "sprofile trace\n", path); + exit(1); + } + samples_total += s_total; + samples_idle += s_idle; + samples_system += s_system; + samples_user += s_user; + + /* read and store samples */ + samples_read = 0; + while (fread(&sample, sizeof(sample), 1, file) == 1) { + sample_store(&sample); + samples_read++; + } + if (samples_read != s_system) { + fprintf(stderr, "warning: number of system samples (%d) in " + "\"%s\" does not match number of records (%d)\n", + s_system, path, samples_read); + } + if (!feof(file)) { + fprintf(stderr, "warning: partial sample at end of \"%s\", " + "was the trace file truncated?\n", path); + } + fclose(file); +} + +static void *malloc_checked(size_t size) { + void *p; + if (!size) return NULL; + p = malloc(size); + if (!p) { + fprintf(stderr, "error: malloc cannot allocate %lu bytes: %s\n", + (unsigned long) size, strerror(errno)); + exit(-1); + } + return p; +} + +static unsigned name_hash(const char *name) { + int i; + unsigned r = 0; + + /* remember: strncpy initializes all bytes */ + for (i = 0; i < BINARY_NAME_SIZE && name[i]; i++) { + r = r * 31 + name[i]; + } + dprintf("name_hash(\"%.*s) = 0x%.8x\n", BINARY_NAME_SIZE, name, r); + return r; +} + +static float percent(int value, int percent_of) { + assert(value >= 0); + assert(value <= percent_of); + + return (percent_of > 0) ? (value * 100.0 / percent_of) : 0; +} + +static void print_report(void) { + printf("Showing processes and functions using at least %3.0f%% " + "time.\n\n", minimum_perc); + printf(" System process ticks: %10d (%3.0f%%)\n", + samples_system, percent(samples_system, samples_total)); + printf(" User process ticks: %10d (%3.0f%%) " + "Details of system process\n", + samples_user, percent(samples_user, samples_total)); + printf(" Idle time ticks: %10d (%3.0f%%) " + "samples, aggregated and\n", + samples_idle, percent(samples_idle, samples_total)); + printf(" ---------- ---- " + "per process, are below.\n"); + printf(" Total ticks: %10d (100%%)\n\n", samples_total); + + print_report_overall(); + print_reports_per_binary(); +} + +static void print_report_overall(void) { + struct binary_info *binary; + struct symbol_count *symbol, **symbols_sorted; + unsigned index, symbol_count; + int sample_threshold; + + /* count number of symbols to display */ + sample_threshold = samples_system * minimum_perc / 100; + symbol_count = 0; + for (binary = binaries; binary; binary = binary->next) { + symbol_count += count_symbols(binary, sample_threshold); + } + + /* sort symbols by decreasing number of samples */ + symbols_sorted = MALLOC_CHECKED(struct symbol_count *, symbol_count); + index = 0; + for (binary = binaries; binary; binary = binary->next) { + for (symbol = binary->symbols; symbol; symbol = symbol->next) { + if (symbol->samples >= sample_threshold) { + symbols_sorted[index++] = symbol; + } + } + } + assert(index == symbol_count); + qsort(symbols_sorted, symbol_count, sizeof(symbols_sorted[0]), + compare_symbols); + + /* report most common symbols overall */ + print_separator(); + printf("Total system process time %*d samples\n", + LINE_WIDTH - 34, samples_system); + print_separator(); + print_report_symbols(symbols_sorted, symbol_count, samples_system, 1); + free(symbols_sorted); +} + +static void print_report_per_binary(const struct binary_info *binary) { + struct symbol_count *symbol, **symbols_sorted; + unsigned index, symbol_count; + int sample_threshold; + + /* count number of symbols to display */ + sample_threshold = binary->samples * minimum_perc / 100; + symbol_count = count_symbols(binary, sample_threshold); + + /* sort symbols by decreasing number of samples */ + symbols_sorted = MALLOC_CHECKED(struct symbol_count *, symbol_count); + index = 0; + for (symbol = binary->symbols; symbol; symbol = symbol->next) { + if (symbol->samples >= sample_threshold) { + symbols_sorted[index++] = symbol; + } + } + assert(index == symbol_count); + qsort(symbols_sorted, symbol_count, sizeof(symbols_sorted[0]), + compare_symbols); + + /* report most common symbols for this binary */ + print_separator(); + printf("%-*.*s %4.1f%% of system process samples\n", + LINE_WIDTH - 32, BINARY_NAME_SIZE, binary->name, + percent(binary->samples, samples_system)); + print_separator(); + print_report_symbols(symbols_sorted, symbol_count, binary->samples, 0); + free(symbols_sorted); +} + +static void print_reports_per_binary(void) { + struct binary_info *binary, **binaries_sorted; + unsigned binary_count, i, index; + int sample_threshold, samples_shown; + struct symbol_count *symbol; + + /* count total per-binary samples */ + binary_count = 0; + for (binary = binaries; binary; binary = binary->next) { + assert(!binary->samples); + for (symbol = binary->symbols; symbol; symbol = symbol->next) { + binary->samples += symbol->samples; + } + binary_count++; + } + + /* sort binaries by decreasing number of samples */ + binaries_sorted = MALLOC_CHECKED(struct binary_info *, binary_count); + index = 0; + for (binary = binaries; binary; binary = binary->next) { + binaries_sorted[index++] = binary; + } + assert(index == binary_count); + qsort(binaries_sorted, binary_count, sizeof(binaries_sorted[0]), + compare_binaries); + + /* display reports for binaries with enough samples */ + sample_threshold = samples_system * minimum_perc / 100; + samples_shown = 0; + for (i = 0; i < binary_count; i++) { + if (binaries_sorted[i]->samples < sample_threshold) break; + print_report_per_binary(binaries_sorted[i]); + samples_shown += binaries_sorted[i]->samples; + } + print_separator(); + printf("processes <%3.0f%% (not showing functions) %*.1f%% of system " + "process samples\n", minimum_perc, LINE_WIDTH - 60, + percent(samples_system - samples_shown, samples_system)); + print_separator(); + + free(binaries_sorted); +} + +static void print_report_symbols(struct symbol_count **symbols, + unsigned symbol_count, int total, int show_process) { + unsigned bar_dots, bar_width, i, j, process_width; + int samples, samples_shown; + struct symbol_count *symbol; + + /* find out how much space we have available */ + process_width = show_process ? (BINARY_NAME_SIZE + 1) : 0; + bar_width = LINE_WIDTH - process_width - SYMBOL_NAME_WIDTH - 17; + + /* print the symbol lines */ + samples_shown = 0; + for (i = 0; i <= symbol_count; i++) { + if (i < symbol_count) { + /* first list the symbols themselves */ + symbol = symbols[i]; + printf("%*.*s %*.*s ", + process_width, + show_process ? BINARY_NAME_SIZE : 0, + symbol->binary->name, + SYMBOL_NAME_WIDTH, + SYMBOL_NAME_WIDTH, + symbol->name); + samples = symbol->samples; + } else { + /* at the end, list the remainder */ + printf("%*s<%3.0f%% ", + process_width + SYMBOL_NAME_WIDTH - 4, + "", + minimum_perc); + samples = total - samples_shown; + } + assert(samples >= 0); + assert(samples <= total); + bar_dots = (total > 0) ? (samples * bar_width / total) : 0; + for (j = 0; j < bar_dots; j++) printf("*"); + for (; j < bar_width; j++) printf(" "); + printf("%8d %5.1f%%\n", samples, percent(samples, total)); + samples_shown += samples; + } + + /* print remainder and summary */ + print_separator(); + printf("%-*.*s%*d 100.0%%\n\n", BINARY_NAME_SIZE, BINARY_NAME_SIZE, + (show_process || symbol_count == 0) ? + "total" : symbols[0]->binary->name, + LINE_WIDTH - BINARY_NAME_SIZE - 7, total); +} + +static void print_separator(void) { + int i; + for (i = 0; i < LINE_WIDTH; i++) printf("-"); + printf("\n"); +} + +static int read_hex(FILE *file, unsigned long *value) { + int c, cvalue; + unsigned index; + + assert(file); + assert(value); + + index = 0; + c = fgetc(file); + *value = 0; + while (index < 8) { + if (c >= '0' && c <= '9') { + cvalue = c - '0'; + } else if (c >= 'A' && c <= 'F') { + cvalue = c - 'A' + 10; + } else if (c >= 'a' && c <= 'f') { + cvalue = c - 'a' + 10; + } else { + break; + } + + *value = *value * 16 + cvalue; + index++; + c = fgetc(file); + } + if (c != EOF) ungetc(c, file); + + return index; +} + +static int read_newline(FILE *file) { + int c; + + do { + c = fgetc(file); + } while (c != EOF && c != '\n' && isspace(c)); + if (c == EOF || c == '\n') return 1; + ungetc(c, file); + return 0; +} + +static void read_nm_line(FILE *file, int line, char *name, char *type, + unsigned long *addr, unsigned long *size) { + + assert(file); + assert(name); + assert(type); + assert(addr); + assert(size); + *type = 0; + *addr = 0; + *size = 0; + if (read_newline(file)) { + memset(name, 0, SYMBOL_NAME_SIZE); + return; + } + + /* name and type are compulsory */ + read_to_whitespace(file, name, SYMBOL_NAME_SIZE); + if (read_newline(file)) { + fprintf(stderr, "error: bad output format from nm: " + "symbol type missing on line %d\n", line); + exit(-1); + } + *type = fgetc(file); + + /* address is optional */ + if (read_newline(file)) return; + if (!read_hex(file, addr)) { + fprintf(stderr, "error: bad output format from nm: junk where " + "address should be on line %d\n", line); + exit(-1); + } + + /* size is optional */ + if (read_newline(file)) return; + if (!read_hex(file, size)) { + fprintf(stderr, "error: bad output format from nm: junk where " + "size should be on line %d\n", line); + exit(-1); + } + + /* nothing else expected */ + if (read_newline(file)) return; + fprintf(stderr, "error: bad output format from nm: junk after size " + "on line %d\n", line); + exit(-1); +} + +static void read_to_whitespace(FILE *file, char *buffer, size_t size) { + int c; + + /* read up to and incl first whitespace, store at most size chars */ + while ((c = fgetc(file)) != EOF && !isspace(c)) { + if (size > 0) { + *(buffer++) = c; + size--; + } + } + if (size > 0) *buffer = 0; +} + +static void sample_store(const struct trace_sample *sample) { + struct binary_info *binary; + int index_l1; + char path[PATH_MAX + 1]; + struct pc_map_l2 *pc_map_l2; + struct symbol_count *symbol; + + /* locate binary */ + binary = binary_find(sample->name); + if (!binary) { + fprintf(stderr, "warning: ignoring unknown binary \"%.*s\"\n", + BINARY_NAME_SIZE, sample->name); + fprintf(stderr, " did you include this executable in " + "the configuration?\n"); + fprintf(stderr, " (use -b to add additional " + "binaries)\n"); + + /* prevent additional warnings by adding bogus binary */ + snprintf(path, sizeof(path), "/DOESNOTEXIST/%.*s", + BINARY_NAME_SIZE, sample->name); + binary = binary_add(strdup_checked(path)); + binary->no_more_warnings = 1; + return; + } + + /* load symbols if this hasn't been done yet */ + if (!binary->pc_map) { + binary_load_pc_map(binary); + if (!binary->pc_map) return; + } + + /* find the applicable symbol (two-level lookup) */ + index_l1 = sample->pc / PC_MAP_L2_SIZE; + assert(index_l1 < PC_MAP_L1_SIZE); + pc_map_l2 = binary->pc_map->l1[index_l1]; + if (pc_map_l2) { + symbol = pc_map_l2->l2[sample->pc % PC_MAP_L2_SIZE]; + } else { + symbol = NULL; + } + + if (symbol) { + symbol->samples++; + } else if (!binary->no_more_warnings) { + fprintf(stderr, "warning: address 0x%lx not associated with a " + "symbol\n", (unsigned long) sample->pc); + fprintf(stderr, " binary may not match the profiled " + "version\n"); + fprintf(stderr, " path: \"%s\"\n", binary->path); + binary->no_more_warnings = 1; + } +} + +static char *strdup_checked(const char *s) { + char *p; + if (!s) return NULL; + p = strdup(s); + if (!p) { + fprintf(stderr, "error: strdup failed: %s\n", + strerror(errno)); + exit(-1); + } + return p; +} + +static void usage(const char *argv0) { + printf("usage:\n"); + printf(" %s [-p percentage] [-s src-tree-path] " + "[-b binary]... file...\n", argv0); + exit(1); +}