[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 <mcb30@ipxe.org>

1 files changed, 107 insertions, 39 deletions

diff --git a/src/core/fnrec.c b/src/core/fnrec.c
index 888a4a27..05d63aaa 100644
--- a/src/core/fnrec.c
+++ b/src/core/fnrec.c
@@ -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();
+	}
 }