]> git.ipfire.org Git - thirdparty/ipxe.git/commitdiff
[fnrec] Enhance function recording
authorMichael Brown <mcb30@ipxe.org>
Sat, 4 Dec 2010 02:55:11 +0000 (02:55 +0000)
committerMichael Brown <mcb30@ipxe.org>
Thu, 9 Dec 2010 13:11:27 +0000 (13:11 +0000)
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 <mcb30@ipxe.org>
src/core/fnrec.c
src/include/compiler.h
src/util/fnrec.pl [new file with mode: 0755]
src/util/fnrec.sh [deleted file]

index 888a4a2772e3023f3f14e23fe0982b4a80c6ed7c..05d63aaa84b2d3472025e44508f533cc2fbe12c3 100644 (file)
@@ -23,6 +23,7 @@ FILE_LICENCE ( GPL2_OR_LATER );
 #include <string.h>
 #include <ipxe/init.h>
 #include <ipxe/uaccess.h>
+#include <ipxe/io.h>
 
 /** @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' )
+
+/** Number of trace buffer entries */
+#define FNREC_NUM_ENTRIES 4096
 
-       /** Trace buffer length */
-       fnrec_buffer_length = 4096 / sizeof ( unsigned long ),
+/** 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;
-
-       /* Avoid recording the same value repeatedly */
-       if ( l == lastval )
-               return;
+static struct fnrec_entry * fnrec_append ( void *called_fn, void *call_site ) {
+       struct fnrec_entry *entry;
+
+       /* 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();
+       }
 }
index f3f713000177851645596aded957923c307be911..771e0610b564a42f0e39a2addcd87b43cf212317 100644 (file)
@@ -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 (executable)
index 0000000..9a2b3d8
--- /dev/null
@@ -0,0 +1,145 @@
+#!/usr/bin/perl -w
+#
+# Copyright (C) 2010 Michael Brown <mbrown@fensystems.co.uk>.
+#
+# 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 (executable)
index 3be5cea..0000000
+++ /dev/null
@@ -1,32 +0,0 @@
-#!/bin/bash
-#
-# Copyright (C) 2010 Stefan Hajnoczi <stefanha@gmail.com>.
-#
-# 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 <<EOF
-usage: $0 <elf-binary> <addresses-file>
-Look up symbol names in <elf-binary> for function addresses from
-<addresses-file>.
-
-Example:
-$0 bin/ipxe.hd.tmp fnrec.dat
-EOF
-       exit 1
-fi
-
-tr ' ' '\n' <"$2" | addr2line -fe "$1" | awk '(NR % 2) { print }'