From ea0fcb9460403a16d4e2a5e1d48ee6279794450c Mon Sep 17 00:00:00 2001 From: Michael Brown Date: Sat, 4 Dec 2010 02:55:11 +0000 Subject: [PATCH] [fnrec] Enhance function recording Enhance the information collected by the function recorder to include the call site and entry/exit counts. This allows fnrec.pl to produce a call tree such as: step (from core/getkey.c:46 = 0x17e90) { ref_increment (from core/process.c:93 = 0x73ec) { } net_step (from core/process.c:96 = 0x73f1) { net_poll (from net/netdevice.c:741 = 0xbce6) { netdev_poll (from net/netdevice.c:700 = 0xbc58) { } netdev_rx_dequeue (from net/netdevice.c:709 = 0xbc65) { } } } ref_decrement (from core/process.c:96 = 0x73f9) { } } Note that inlined functions are reported, confusingly, as extra calls to the *containing* function. Minimise this confusion by adding the attribute "no_instrument_function" to all functions declared as inline. (Static functions that have been inlined autonomously by gcc will still be problematic, but these are far fewer in number.) Signed-off-by: Michael Brown --- src/core/fnrec.c | 144 +++++++++++++++++++++++++++++----------- src/include/compiler.h | 13 ++++ src/util/fnrec.pl | 145 +++++++++++++++++++++++++++++++++++++++++ src/util/fnrec.sh | 32 --------- 4 files changed, 264 insertions(+), 70 deletions(-) create mode 100755 src/util/fnrec.pl delete mode 100755 src/util/fnrec.sh diff --git a/src/core/fnrec.c b/src/core/fnrec.c index 888a4a277..05d63aaa8 100644 --- a/src/core/fnrec.c +++ b/src/core/fnrec.c @@ -23,6 +23,7 @@ FILE_LICENCE ( GPL2_OR_LATER ); #include #include #include +#include /** @file * @@ -30,12 +31,30 @@ FILE_LICENCE ( GPL2_OR_LATER ); * */ -enum { - /** Constant for identifying valid trace buffers */ - fnrec_magic = 'f' << 24 | 'n' << 16 | 'r' << 8 | 'e', +/** Constant for identifying valid trace buffers */ +#define FNREC_MAGIC ( 'f' << 24 | 'n' << 16 | 'r' << 8 | 'e' ) - /** Trace buffer length */ - fnrec_buffer_length = 4096 / sizeof ( unsigned long ), +/** Number of trace buffer entries */ +#define FNREC_NUM_ENTRIES 4096 + +/** Trace buffer physical address + * + * Fixed at 17MB + */ +#define FNREC_PHYS_ADDRESS ( 17 * 1024 * 1024 ) + +/** A trace buffer entry */ +struct fnrec_entry { + /** Called function address */ + void *called_fn; + /** Call site */ + void *call_site; + /** Entry count */ + uint16_t entry_count; + /** Exit count */ + uint16_t exit_count; + /** Checksum */ + unsigned long checksum; }; /** A trace buffer */ @@ -44,10 +63,11 @@ struct fnrec_buffer { uint32_t magic; /** Next trace buffer entry to fill */ - uint32_t idx; + unsigned int idx; - /** Function address trace buffer */ - unsigned long data[fnrec_buffer_length]; + /** Trace buffer */ + struct fnrec_entry data[FNREC_NUM_ENTRIES] + __attribute__ (( aligned ( 64 ) )); }; /** The trace buffer */ @@ -59,7 +79,15 @@ static struct fnrec_buffer *fnrec_buffer; * @ret is_valid Buffer is valid */ static int fnrec_is_valid ( void ) { - return fnrec_buffer && fnrec_buffer->magic == fnrec_magic; + return ( fnrec_buffer && ( fnrec_buffer->magic == FNREC_MAGIC ) ); +} + +/** + * Invalidate the trace buffer + * + */ +static void fnrec_invalidate ( void ) { + fnrec_buffer->magic = 0; } /** @@ -67,43 +95,64 @@ static int fnrec_is_valid ( void ) { */ static void fnrec_reset ( void ) { memset ( fnrec_buffer, 0, sizeof ( *fnrec_buffer ) ); - fnrec_buffer->magic = fnrec_magic; + fnrec_buffer->magic = FNREC_MAGIC; } /** - * Write a value to the end of the buffer if it is not a repetition + * Append an entry to the trace buffer * - * @v l Value to append + * @v called_fn Called function + * @v call_site Call site + * @ret entry Trace buffer entry */ -static void fnrec_append_unique ( unsigned long l ) { - static unsigned long lastval; - uint32_t idx = fnrec_buffer->idx; +static struct fnrec_entry * fnrec_append ( void *called_fn, void *call_site ) { + struct fnrec_entry *entry; - /* Avoid recording the same value repeatedly */ - if ( l == lastval ) - return; + /* Re-use existing entry, if possible */ + entry = &fnrec_buffer->data[ fnrec_buffer->idx ]; + if ( ( entry->called_fn == called_fn ) && + ( entry->call_site == call_site ) && + ( entry->entry_count >= entry->exit_count ) ) { + return entry; + } - fnrec_buffer->data[idx] = l; - fnrec_buffer->idx = ( idx + 1 ) % fnrec_buffer_length; - lastval = l; + /* Otherwise, create a new entry */ + fnrec_buffer->idx = ( ( fnrec_buffer->idx + 1 ) % FNREC_NUM_ENTRIES ); + entry = &fnrec_buffer->data[ fnrec_buffer->idx ]; + entry->called_fn = called_fn; + entry->call_site = call_site; + entry->entry_count = 0; + entry->exit_count = 0; + entry->checksum = ( ( ( unsigned long ) called_fn ) ^ + ( ( unsigned long ) call_site ) ); + return entry; } /** * Print the contents of the trace buffer in chronological order */ static void fnrec_dump ( void ) { - size_t i; - - if ( !fnrec_is_valid() ) { - printf ( "fnrec buffer not found\n" ); - return; - } + struct fnrec_entry *entry; + unsigned int i; + unsigned int idx; + unsigned long checksum; printf ( "fnrec buffer dump:\n" ); - for ( i = 0; i < fnrec_buffer_length; i++ ) { - unsigned long l = fnrec_buffer->data[ - ( fnrec_buffer->idx + i ) % fnrec_buffer_length]; - printf ( "%08lx%c", l, i % 8 == 7 ? '\n' : ' ' ); + for ( i = 1 ; i <= FNREC_NUM_ENTRIES ; i++ ) { + idx = ( ( fnrec_buffer->idx + i ) % FNREC_NUM_ENTRIES ); + entry = &fnrec_buffer->data[idx]; + if ( ( entry->entry_count == 0 ) && ( entry->exit_count == 0 ) ) + continue; + checksum = ( ( ( ( unsigned long ) entry->called_fn ) ^ + ( ( unsigned long ) entry->call_site ) ) + + entry->entry_count + entry->exit_count ); + printf ( "%p %p %d %d", entry->called_fn, entry->call_site, + entry->entry_count, entry->exit_count ); + if ( entry->checksum != checksum ) { + printf ( " (checksum wrong at phys %08lx)", + virt_to_phys ( entry ) ); + } + printf ( "\n"); } } @@ -111,9 +160,14 @@ static void fnrec_dump ( void ) { * Function tracer initialisation function */ static void fnrec_init ( void ) { - /* Hardcoded to 17 MB */ - fnrec_buffer = phys_to_virt ( 17 * 1024 * 1024 ); - fnrec_dump(); + + fnrec_buffer = phys_to_virt ( FNREC_PHYS_ADDRESS ); + if ( fnrec_is_valid() ) { + fnrec_invalidate(); + fnrec_dump(); + } else { + printf ( "fnrec buffer not found\n" ); + } fnrec_reset(); } @@ -125,10 +179,24 @@ struct init_fn fnrec_init_fn __init_fn ( INIT_NORMAL ) = { * These functions are called from every C function. The compiler inserts * these calls when -finstrument-functions is used. */ -void __cyg_profile_func_enter ( void *called_fn, void *call_site __unused ) { - if ( fnrec_is_valid() ) - fnrec_append_unique ( ( unsigned long ) called_fn ); +void __cyg_profile_func_enter ( void *called_fn, void *call_site ) { + struct fnrec_entry *entry; + + if ( fnrec_is_valid() ) { + entry = fnrec_append ( called_fn, call_site ); + entry->entry_count++; + entry->checksum++; + mb(); + } } -void __cyg_profile_func_exit ( void *called_fn __unused, void *call_site __unused ) { +void __cyg_profile_func_exit ( void *called_fn, void *call_site ) { + struct fnrec_entry *entry; + + if ( fnrec_is_valid() ) { + entry = fnrec_append ( called_fn, call_site ); + entry->exit_count++; + entry->checksum++; + mb(); + } } diff --git a/src/include/compiler.h b/src/include/compiler.h index f3f713000..771e0610b 100644 --- a/src/include/compiler.h +++ b/src/include/compiler.h @@ -537,6 +537,19 @@ int __debug_disable; /** Declare a function to be always inline */ #define __always_inline __attribute__ (( always_inline )) +/* Force all inline functions to not be instrumented + * + * This is required to cope with what seems to be a long-standing gcc + * bug, in which -finstrument-functions will cause instances of + * inlined functions to be reported as further calls to the + * *containing* function. This makes instrumentation very difficult + * to use. + * + * Work around this problem by adding the no_instrument_function + * attribute to all inlined functions. + */ +#define inline inline __attribute__ (( no_instrument_function )) + /** * Shared data. * diff --git a/src/util/fnrec.pl b/src/util/fnrec.pl new file mode 100755 index 000000000..9a2b3d81f --- /dev/null +++ b/src/util/fnrec.pl @@ -0,0 +1,145 @@ +#!/usr/bin/perl -w +# +# Copyright (C) 2010 Michael Brown . +# +# This program is free software; you can redistribute it and/or +# modify it under the terms of the GNU General Public License as +# published by the Free Software Foundation; either version 2 of the +# License, or any later version. +# +# This program is distributed in the hope that it will be useful, but +# WITHOUT ANY WARRANTY; without even the implied warranty of +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +# General Public License for more details. +# +# You should have received a copy of the GNU General Public License +# along with this program; if not, write to the Free Software +# Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. + +=head1 NAME + +fnrec.pl + +=head1 SYNOPSIS + +fnrec.pl [options] bin/image.xxx < logfile + +Decode a function trace produced by building with FNREC=1 + +Options: + + -m,--max-depth=N Set maximum displayed function depth + +=cut + +use IPC::Open2; +use Getopt::Long; +use Pod::Usage; +use strict; +use warnings; + +use constant MAX_OPEN_BRACE => 10; +use constant MAX_COMMON_BRACE => 3; +use constant MAX_CLOSE_BRACE => 10; + +# Parse command-line options +my $max_depth = 16; +Getopt::Long::Configure ( 'bundling', 'auto_abbrev' ); +GetOptions ( + 'help|h' => sub { pod2usage ( 1 ); }, + 'max-depth|m=i' => sub { shift; $max_depth = shift; }, +) or die "Could not parse command-line options\n"; +pod2usage ( 1 ) unless @ARGV == 1; +my $image = shift; +my $elf = $image.".tmp"; +die "ELF file ".$elf." not found\n" unless -e $elf; + +# Start up addr2line +my $addr2line_pid = open2 ( my $addr2line_out, my $addr2line_in, + "addr2line", "-f", "-e", $elf ) + or die "Could not start addr2line: $!\n"; + +# Translate address using addr2line +sub addr2line { + my $address = shift; + + print $addr2line_in $address."\n"; + chomp ( my $name = <$addr2line_out> ); + chomp ( my $file_line = <$addr2line_out> ); + ( my $file, my $line ) = ( $file_line =~ /^(.*):(\d+)$/ ); + $file =~ s/^.*\/src\///; + my $location = ( $line ? $file.":".$line." = ".$address : $address ); + return ( $name, $location ); +} + +# Parse logfile +my $depth = 0; +my $depths = []; +while ( my $line = <> ) { + chomp $line; + $line =~ s/\r//g; + ( my $called_fn, my $call_site, my $entry_count, my $exit_count ) = + ( $line =~ /^(0x[0-9a-f]+)\s+(0x[0-9a-f]+)\s+([0-9]+)\s+([0-9]+)$/ ) + or print $line."\n" and next; + + ( my $called_fn_name, undef ) = addr2line ( $called_fn ); + ( undef, my $call_site_location ) = addr2line ( $call_site ); + $entry_count = ( $entry_count + 0 ); + $exit_count = ( $exit_count + 0 ); + + if ( $entry_count >= $exit_count ) { + # + # Function entry + # + my $text = ""; + $text .= $called_fn_name." (from ".$call_site_location.")"; + if ( $exit_count <= MAX_COMMON_BRACE ) { + $text .= " { }" x $exit_count; + } else { + $text .= " { } x ".$exit_count; + } + $entry_count -= $exit_count; + if ( $entry_count <= MAX_OPEN_BRACE ) { + $text .= " {" x $entry_count; + } else { + $text .= " { x ".$entry_count; + } + my $indent = " " x $depth; + print $indent.$text."\n"; + $depth += $entry_count; + $depth = $max_depth if ( $depth > $max_depth ); + push @$depths, ( { called_fn => $called_fn, call_site => $call_site } ) x + ( $depth - @$depths ); + } else { + # + # Function exit + # + my $text = ""; + if ( $entry_count <= MAX_COMMON_BRACE ) { + $text .= " { }" x $entry_count; + } else { + $text .= " { } x ".$entry_count; + } + $exit_count -= $entry_count; + if ( $exit_count <= MAX_CLOSE_BRACE ) { + $text .= " }" x $exit_count; + } else { + $text .= " } x ".$exit_count; + } + $depth -= $exit_count; + $depth = 0 if ( $depth < 0 ); + if ( ( @$depths == 0 ) || + ( $depths->[$depth]->{called_fn} ne $called_fn ) || + ( $depths->[$depth]->{call_site} ne $call_site ) ) { + $text .= " (from ".$called_fn_name." to ".$call_site_location.")"; + } + splice ( @$depths, $depth ); + my $indent = " " x $depth; + print substr ( $indent.$text, 1 )."\n"; + } +} + +# Clean up addr2line +close $addr2line_in; +close $addr2line_out; +waitpid ( $addr2line_pid, 0 ); diff --git a/src/util/fnrec.sh b/src/util/fnrec.sh deleted file mode 100755 index 3be5ceaa7..000000000 --- a/src/util/fnrec.sh +++ /dev/null @@ -1,32 +0,0 @@ -#!/bin/bash -# -# Copyright (C) 2010 Stefan Hajnoczi . -# -# This program is free software; you can redistribute it and/or -# modify it under the terms of the GNU General Public License as -# published by the Free Software Foundation; either version 2 of the -# License, or any later version. -# -# This program is distributed in the hope that it will be useful, but -# WITHOUT ANY WARRANTY; without even the implied warranty of -# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU -# General Public License for more details. -# -# You should have received a copy of the GNU General Public License -# along with this program; if not, write to the Free Software -# Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. - -if [ $# != 2 ] -then - cat >&2 < -Look up symbol names in for function addresses from -. - -Example: -$0 bin/ipxe.hd.tmp fnrec.dat -EOF - exit 1 -fi - -tr ' ' '\n' <"$2" | addr2line -fe "$1" | awk '(NR % 2) { print }'