Browse Source

[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>
tags/v1.20.1
Michael Brown 14 years ago
parent
commit
ea0fcb9460
4 changed files with 265 additions and 71 deletions
  1. 107
    39
      src/core/fnrec.c
  2. 13
    0
      src/include/compiler.h
  3. 145
    0
      src/util/fnrec.pl
  4. 0
    32
      src/util/fnrec.sh

+ 107
- 39
src/core/fnrec.c View File

@@ -23,6 +23,7 @@ FILE_LICENCE ( GPL2_OR_LATER );
23 23
 #include <string.h>
24 24
 #include <ipxe/init.h>
25 25
 #include <ipxe/uaccess.h>
26
+#include <ipxe/io.h>
26 27
 
27 28
 /** @file
28 29
  *
@@ -30,12 +31,30 @@ FILE_LICENCE ( GPL2_OR_LATER );
30 31
  *
31 32
  */
32 33
 
33
-enum {
34
-	/** Constant for identifying valid trace buffers */
35
-	fnrec_magic = 'f' << 24 | 'n' << 16 | 'r' << 8 | 'e',
34
+/** Constant for identifying valid trace buffers */
35
+#define FNREC_MAGIC ( 'f' << 24 | 'n' << 16 | 'r' << 8 | 'e' )
36
+
37
+/** Number of trace buffer entries */
38
+#define FNREC_NUM_ENTRIES 4096
36 39
 
37
-	/** Trace buffer length */
38
-	fnrec_buffer_length = 4096 / sizeof ( unsigned long ),
40
+/** Trace buffer physical address
41
+ *
42
+ * Fixed at 17MB
43
+ */
44
+#define FNREC_PHYS_ADDRESS ( 17 * 1024 * 1024 )
45
+
46
+/** A trace buffer entry */
47
+struct fnrec_entry {
48
+	/** Called function address */
49
+	void *called_fn;
50
+	/** Call site */
51
+	void *call_site;
52
+	/** Entry count */
53
+	uint16_t entry_count;
54
+	/** Exit count */
55
+	uint16_t exit_count;
56
+	/** Checksum */
57
+	unsigned long checksum;
39 58
 };
40 59
 
41 60
 /** A trace buffer */
@@ -44,10 +63,11 @@ struct fnrec_buffer {
44 63
 	uint32_t magic;
45 64
 
46 65
 	/** Next trace buffer entry to fill */
47
-	uint32_t idx;
66
+	unsigned int idx;
48 67
 
49
-	/** Function address trace buffer */
50
-	unsigned long data[fnrec_buffer_length];
68
+	/** Trace buffer */
69
+	struct fnrec_entry data[FNREC_NUM_ENTRIES]
70
+		__attribute__ (( aligned ( 64 ) ));
51 71
 };
52 72
 
53 73
 /** The trace buffer */
@@ -59,7 +79,15 @@ static struct fnrec_buffer *fnrec_buffer;
59 79
  * @ret is_valid	Buffer is valid
60 80
  */
61 81
 static int fnrec_is_valid ( void ) {
62
-	return fnrec_buffer && fnrec_buffer->magic == fnrec_magic;
82
+	return ( fnrec_buffer && ( fnrec_buffer->magic == FNREC_MAGIC ) );
83
+}
84
+
85
+/**
86
+ * Invalidate the trace buffer
87
+ *
88
+ */
89
+static void fnrec_invalidate ( void ) {
90
+	fnrec_buffer->magic = 0;
63 91
 }
64 92
 
65 93
 /**
@@ -67,43 +95,64 @@ static int fnrec_is_valid ( void ) {
67 95
  */
68 96
 static void fnrec_reset ( void ) {
69 97
 	memset ( fnrec_buffer, 0, sizeof ( *fnrec_buffer ) );
70
-	fnrec_buffer->magic = fnrec_magic;
98
+	fnrec_buffer->magic = FNREC_MAGIC;
71 99
 }
72 100
 
73 101
 /**
74
- * Write a value to the end of the buffer if it is not a repetition
102
+ * Append an entry to the trace buffer
75 103
  *
76
- * @v l			Value to append
104
+ * @v called_fn		Called function
105
+ * @v call_site		Call site
106
+ * @ret entry		Trace buffer entry
77 107
  */
78
-static void fnrec_append_unique ( unsigned long l ) {
79
-	static unsigned long lastval;
80
-	uint32_t idx = fnrec_buffer->idx;
81
-
82
-	/* Avoid recording the same value repeatedly */
83
-	if ( l == lastval )
84
-		return;
108
+static struct fnrec_entry * fnrec_append ( void *called_fn, void *call_site ) {
109
+	struct fnrec_entry *entry;
110
+
111
+	/* Re-use existing entry, if possible */
112
+	entry = &fnrec_buffer->data[ fnrec_buffer->idx ];
113
+	if ( ( entry->called_fn == called_fn ) &&
114
+	     ( entry->call_site == call_site ) &&
115
+	     ( entry->entry_count >= entry->exit_count ) ) {
116
+		return entry;
117
+	}
85 118
 
86
-	fnrec_buffer->data[idx] = l;
87
-	fnrec_buffer->idx = ( idx + 1 ) % fnrec_buffer_length;
88
-	lastval = l;
119
+	/* Otherwise, create a new entry */
120
+	fnrec_buffer->idx = ( ( fnrec_buffer->idx + 1 ) % FNREC_NUM_ENTRIES );
121
+	entry = &fnrec_buffer->data[ fnrec_buffer->idx ];
122
+	entry->called_fn = called_fn;
123
+	entry->call_site = call_site;
124
+	entry->entry_count = 0;
125
+	entry->exit_count = 0;
126
+	entry->checksum = ( ( ( unsigned long ) called_fn ) ^
127
+			    ( ( unsigned long ) call_site ) );
128
+	return entry;
89 129
 }
90 130
 
91 131
 /**
92 132
  * Print the contents of the trace buffer in chronological order
93 133
  */
94 134
 static void fnrec_dump ( void ) {
95
-	size_t i;
96
-
97
-	if ( !fnrec_is_valid() ) {
98
-		printf ( "fnrec buffer not found\n" );
99
-		return;
100
-	}
135
+	struct fnrec_entry *entry;
136
+	unsigned int i;
137
+	unsigned int idx;
138
+	unsigned long checksum;
101 139
 
102 140
 	printf ( "fnrec buffer dump:\n" );
103
-	for ( i = 0; i < fnrec_buffer_length; i++ ) {
104
-		unsigned long l = fnrec_buffer->data[
105
-			( fnrec_buffer->idx + i ) % fnrec_buffer_length];
106
-		printf ( "%08lx%c", l, i % 8 == 7 ? '\n' : ' ' );
141
+	for ( i = 1 ; i <= FNREC_NUM_ENTRIES ; i++ ) {
142
+		idx = ( ( fnrec_buffer->idx + i ) % FNREC_NUM_ENTRIES );
143
+		entry = &fnrec_buffer->data[idx];
144
+		if ( ( entry->entry_count == 0 ) && ( entry->exit_count == 0 ) )
145
+			continue;
146
+		checksum = ( ( ( ( unsigned long ) entry->called_fn ) ^
147
+			       ( ( unsigned long ) entry->call_site ) ) +
148
+			     entry->entry_count + entry->exit_count );
149
+		printf ( "%p %p %d %d", entry->called_fn, entry->call_site,
150
+			 entry->entry_count, entry->exit_count );
151
+		if ( entry->checksum != checksum ) {
152
+			printf ( " (checksum wrong at phys %08lx)",
153
+				 virt_to_phys ( entry ) );
154
+		}
155
+		printf ( "\n");
107 156
 	}
108 157
 }
109 158
 
@@ -111,9 +160,14 @@ static void fnrec_dump ( void ) {
111 160
  * Function tracer initialisation function
112 161
  */
113 162
 static void fnrec_init ( void ) {
114
-	/* Hardcoded to 17 MB */
115
-	fnrec_buffer = phys_to_virt ( 17 * 1024 * 1024 );
116
-	fnrec_dump();
163
+
164
+	fnrec_buffer = phys_to_virt ( FNREC_PHYS_ADDRESS );
165
+	if ( fnrec_is_valid() ) {
166
+		fnrec_invalidate();
167
+		fnrec_dump();
168
+	} else {
169
+		printf ( "fnrec buffer not found\n" );
170
+	}
117 171
 	fnrec_reset();
118 172
 }
119 173
 
@@ -125,10 +179,24 @@ struct init_fn fnrec_init_fn __init_fn ( INIT_NORMAL ) = {
125 179
  * These functions are called from every C function.  The compiler inserts
126 180
  * these calls when -finstrument-functions is used.
127 181
  */
128
-void __cyg_profile_func_enter ( void *called_fn, void *call_site __unused ) {
129
-	if ( fnrec_is_valid() )
130
-		fnrec_append_unique ( ( unsigned long ) called_fn );
182
+void __cyg_profile_func_enter ( void *called_fn, void *call_site ) {
183
+	struct fnrec_entry *entry;
184
+
185
+	if ( fnrec_is_valid() ) {
186
+		entry = fnrec_append ( called_fn, call_site );
187
+		entry->entry_count++;
188
+		entry->checksum++;
189
+		mb();
190
+	}
131 191
 }
132 192
 
133
-void __cyg_profile_func_exit ( void *called_fn __unused, void *call_site __unused ) {
193
+void __cyg_profile_func_exit ( void *called_fn, void *call_site ) {
194
+	struct fnrec_entry *entry;
195
+
196
+	if ( fnrec_is_valid() ) {
197
+		entry = fnrec_append ( called_fn, call_site );
198
+		entry->exit_count++;
199
+		entry->checksum++;
200
+		mb();
201
+	}
134 202
 }

+ 13
- 0
src/include/compiler.h View File

@@ -537,6 +537,19 @@ int __debug_disable;
537 537
 /** Declare a function to be always inline */
538 538
 #define __always_inline __attribute__ (( always_inline ))
539 539
 
540
+/* Force all inline functions to not be instrumented
541
+ *
542
+ * This is required to cope with what seems to be a long-standing gcc
543
+ * bug, in which -finstrument-functions will cause instances of
544
+ * inlined functions to be reported as further calls to the
545
+ * *containing* function.  This makes instrumentation very difficult
546
+ * to use.
547
+ *
548
+ * Work around this problem by adding the no_instrument_function
549
+ * attribute to all inlined functions.
550
+ */
551
+#define inline inline __attribute__ (( no_instrument_function ))
552
+
540 553
 /**
541 554
  * Shared data.
542 555
  *

+ 145
- 0
src/util/fnrec.pl View File

@@ -0,0 +1,145 @@
1
+#!/usr/bin/perl -w
2
+#
3
+# Copyright (C) 2010 Michael Brown <mbrown@fensystems.co.uk>.
4
+#
5
+# This program is free software; you can redistribute it and/or
6
+# modify it under the terms of the GNU General Public License as
7
+# published by the Free Software Foundation; either version 2 of the
8
+# License, or any later version.
9
+#
10
+# This program is distributed in the hope that it will be useful, but
11
+# WITHOUT ANY WARRANTY; without even the implied warranty of
12
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
13
+# General Public License for more details.
14
+#
15
+# You should have received a copy of the GNU General Public License
16
+# along with this program; if not, write to the Free Software
17
+# Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA.
18
+
19
+=head1 NAME
20
+
21
+fnrec.pl
22
+
23
+=head1 SYNOPSIS
24
+
25
+fnrec.pl [options] bin/image.xxx < logfile
26
+
27
+Decode a function trace produced by building with FNREC=1
28
+
29
+Options:
30
+
31
+	-m,--max-depth=N	Set maximum displayed function depth
32
+
33
+=cut
34
+
35
+use IPC::Open2;
36
+use Getopt::Long;
37
+use Pod::Usage;
38
+use strict;
39
+use warnings;
40
+
41
+use constant MAX_OPEN_BRACE => 10;
42
+use constant MAX_COMMON_BRACE => 3;
43
+use constant MAX_CLOSE_BRACE => 10;
44
+
45
+# Parse command-line options
46
+my $max_depth = 16;
47
+Getopt::Long::Configure ( 'bundling', 'auto_abbrev' );
48
+GetOptions (
49
+  'help|h' => sub { pod2usage ( 1 ); },
50
+  'max-depth|m=i' => sub { shift; $max_depth = shift; },
51
+) or die "Could not parse command-line options\n";
52
+pod2usage ( 1 ) unless @ARGV == 1;
53
+my $image = shift;
54
+my $elf = $image.".tmp";
55
+die "ELF file ".$elf." not found\n" unless -e $elf;
56
+
57
+# Start up addr2line
58
+my $addr2line_pid = open2 ( my $addr2line_out, my $addr2line_in,
59
+			    "addr2line", "-f", "-e", $elf )
60
+    or die "Could not start addr2line: $!\n";
61
+
62
+# Translate address using addr2line
63
+sub addr2line {
64
+  my $address = shift;
65
+
66
+  print $addr2line_in $address."\n";
67
+  chomp ( my $name = <$addr2line_out> );
68
+  chomp ( my $file_line = <$addr2line_out> );
69
+  ( my $file, my $line ) = ( $file_line =~ /^(.*):(\d+)$/ );
70
+  $file =~ s/^.*\/src\///;
71
+  my $location = ( $line ? $file.":".$line." = ".$address : $address );
72
+  return ( $name, $location );
73
+}
74
+
75
+# Parse logfile
76
+my $depth = 0;
77
+my $depths = [];
78
+while ( my $line = <> ) {
79
+  chomp $line;
80
+  $line =~ s/\r//g;
81
+  ( my $called_fn, my $call_site, my $entry_count, my $exit_count ) =
82
+      ( $line =~ /^(0x[0-9a-f]+)\s+(0x[0-9a-f]+)\s+([0-9]+)\s+([0-9]+)$/ )
83
+      or print $line."\n" and next;
84
+
85
+  ( my $called_fn_name, undef ) = addr2line ( $called_fn );
86
+  ( undef, my $call_site_location ) = addr2line ( $call_site );
87
+  $entry_count = ( $entry_count + 0 );
88
+  $exit_count = ( $exit_count + 0 );
89
+
90
+  if ( $entry_count >= $exit_count ) {
91
+    #
92
+    # Function entry
93
+    #
94
+    my $text = "";
95
+    $text .= $called_fn_name." (from ".$call_site_location.")";
96
+    if ( $exit_count <= MAX_COMMON_BRACE ) {
97
+      $text .= " { }" x $exit_count;
98
+    } else {
99
+      $text .= " { } x ".$exit_count;
100
+    }
101
+    $entry_count -= $exit_count;
102
+    if ( $entry_count <= MAX_OPEN_BRACE ) {
103
+      $text .= " {" x $entry_count;
104
+    } else {
105
+      $text .= " { x ".$entry_count;
106
+    }
107
+    my $indent = "  " x $depth;
108
+    print $indent.$text."\n";
109
+    $depth += $entry_count;
110
+    $depth = $max_depth if ( $depth > $max_depth );
111
+    push @$depths, ( { called_fn => $called_fn, call_site => $call_site } ) x
112
+	( $depth - @$depths );
113
+  } else {
114
+    #
115
+    # Function exit
116
+    #
117
+    my $text = "";
118
+    if ( $entry_count <= MAX_COMMON_BRACE ) {
119
+      $text .= " { }" x $entry_count;
120
+    } else {
121
+      $text .= " { } x ".$entry_count;
122
+    }
123
+    $exit_count -= $entry_count;
124
+    if ( $exit_count <= MAX_CLOSE_BRACE ) {
125
+      $text .= " }" x $exit_count;
126
+    } else {
127
+      $text .= " } x ".$exit_count;
128
+    }
129
+    $depth -= $exit_count;
130
+    $depth = 0 if ( $depth < 0 );
131
+    if ( ( @$depths == 0 ) ||
132
+	 ( $depths->[$depth]->{called_fn} ne $called_fn ) ||
133
+	 ( $depths->[$depth]->{call_site} ne $call_site ) ) {
134
+      $text .= " (from ".$called_fn_name." to ".$call_site_location.")";
135
+    }
136
+    splice ( @$depths, $depth );
137
+    my $indent = "  " x $depth;
138
+    print substr ( $indent.$text, 1 )."\n";
139
+  }
140
+}
141
+
142
+# Clean up addr2line
143
+close $addr2line_in;
144
+close $addr2line_out;
145
+waitpid ( $addr2line_pid, 0 );

+ 0
- 32
src/util/fnrec.sh View File

@@ -1,32 +0,0 @@
1
-#!/bin/bash
2
-#
3
-# Copyright (C) 2010 Stefan Hajnoczi <stefanha@gmail.com>.
4
-#
5
-# This program is free software; you can redistribute it and/or
6
-# modify it under the terms of the GNU General Public License as
7
-# published by the Free Software Foundation; either version 2 of the
8
-# License, or any later version.
9
-#
10
-# This program is distributed in the hope that it will be useful, but
11
-# WITHOUT ANY WARRANTY; without even the implied warranty of
12
-# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
13
-# General Public License for more details.
14
-#
15
-# You should have received a copy of the GNU General Public License
16
-# along with this program; if not, write to the Free Software
17
-# Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA.
18
-
19
-if [ $# != 2 ]
20
-then
21
-	cat >&2 <<EOF
22
-usage: $0 <elf-binary> <addresses-file>
23
-Look up symbol names in <elf-binary> for function addresses from
24
-<addresses-file>.
25
-
26
-Example:
27
-$0 bin/ipxe.hd.tmp fnrec.dat
28
-EOF
29
-	exit 1
30
-fi
31
-
32
-tr ' ' '\n' <"$2" | addr2line -fe "$1" | awk '(NR % 2) { print }'

Loading…
Cancel
Save