Skip to contentSkip to conversation

Bootgraph.pl instrumentation support for UBoot

PATCH Superseded Andrew Murray 6 participants 44 messages Aug 31, 2011 – Oct 6, 2011 Arm (32-bit)

lore
Share & tools
lore

Andrew Murray

author
#0 lore raw

cover Bootgraph.pl instrumentation support for UBoot

This patchset introduces the CONFIG_BOOT_TRACE option which provides support for boot time instrumentation.

When enabled printf output is prefixed with timing information (similar to the kernel's CONFIG_PRINTK_TIME option) and additional output is generated which instruments functions and commands called (much like the kernel's initcall_debug functionality).

The kernel's bootgraph.pl script has been ported to render UBoots instrumented ouptut into a pretty SVG graph. An example of this can be found here:
http://goo.gl/dX8aR - which shows the boot time of a Beagle board.

The patch currently provides support for instrumentation of UBoot commands (e.g. U_BOOT_CMD) for all platforms but only when the HUSH shell is not in use. Initialisation instrumentation is only limited to the arch/arm/lib/board.c file at present but can very easily be extended to other relevant files.

The patch also includes documentation.

Andrew Murray (7):
Add bootgraph.pl script for generating a boot graph SVG file Add macros for recording init calls during UBoot execution Add timing information to printf's for use with bootgraph.pl Add bootgraph instrumentation for ARM boards
Add bootgraph instrumentation for bootm command Add bootgraph instrumentation for UBoot commands Add documentation for bootgraph.pl

 arch/arm/lib/board.c |   28 +++++---
 common/cmd_bootm.c   |    1 +
 common/console.c     |   12 +++-
 common/main.c        |   19 +++--
 doc/README.bootgraph |   57 +++++++++++++++
 include/common.h     |   23 ++++++
 tools/bootgraph.pl   |  189 ++++++++++++++++++++++++++++++++++++++++++++++++++
 7 files changed, 312 insertions(+), 17 deletions(-)
 create mode 100644 doc/README.bootgraph
 create mode 100755 tools/bootgraph.pl
Signature · 1 line
1.7.4.1
author
#1 lore raw

PATCH 1/7 Add bootgraph.pl script for generating a boot graph SVG file

From: Andrew Murray <[email protected]>

This is a port of the kernel's script/bootgraph.pl script which generates an SVG image illustrating boot time in UBoot. The script relies on additional output generated by UBoot during boot when the CONFIG_BOOT_TRACE option is enabled.

Signed-off-by Andrew Murray <[email protected]>
---
 tools/bootgraph.pl |  189 ++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 189 insertions(+), 0 deletions(-)
 create mode 100755 tools/bootgraph.pl
tools/bootgraph.pl new file +189 -0
new file mode 100755
index 0000000..8b206b5
@@ -0,0 +1,189 @@
+#!/usr/bin/perl
+
+# Copyright (C) 2011, Andrew Murray <[email protected]>)
+# Copyright (C) 2008, Intel Corporation (Arjan van de Ven <[email protected]>)
+#
+# This program file 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; version 2 of the License.
+#
+# 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 in a file named COPYING; if not, write to the
+# Free Software Foundation, Inc.,
+# 51 Franklin Street, Fifth Floor,
+# Boston, MA 02110-1301 USA
+#
+# This script was originally written by Arjan for use with the Linux kernel and
+# subsequently ported across to UBoot by Andrew.
+#
+# This script turns a output trace from UBoot into a SVG graphic that shows 
+# which functions take how much time. You can view SVG graphics with various
+# programs, including Inkscape, The Gimp and Firefox.
+#
+# For this script to work, the UBoot config file needs to be compiled with the
+# CONFIG_BOOT_TRACE configuration option enabled.
+#
+# usage:
+# 	cat uboot.trace | perl ./tools/bootgraph.pl > output.svg
+#
+
+use strict;
+
+my %start;
+my %end;
+my %type;
+my $done = 0;
+my $maxtime = 0;
+my $firsttime = 99999;
+my $count = 0;
+my $textoffset = hex('0x80008000');
+my $reloffset = $textoffset;
+my %sym;
+
+if (!open FILE, "System.map") {
+	print STDERR <<END;
+No map file found "./System.map". Make sure that a file named
+System.map exists in the current working directory.
+Usage:
+      cat uboot.trace | perl ./tools/bootgraph.pl > output.svg
+END
+	exit 1;
+}
+
+# Read in a map file to support in the printing of function names
+while (<FILE>) {
+	my $line = $_;
+	if ($line =~ /([a-zA-Z0-9]+)\ [a-zA-Z] ([a-zA-Z0-0\_\.]+)/) {
+		$sym{$1} = $2; 
+	}
+}
+close FILE;
+
+# Parse lines of UBoot's trace to generate a timeline
+while (<>) {
+	my $line = $_;
+
+	# Find start of init calls as instrumented in UBoot with DO_INITCALLXXX macros
+	if ($line =~ /([0-9\.]+)\] calling  (0x[a-zA-Z0-9\_\.]+)/) {
+		my $func = sprintf("%x", (hex($2) - $reloffset + $textoffset));
+		$func = $sym{$func};
+		if ($done == 0) {
+			$start{$func} = $1;
+			$type{$func} = 0;
+			if ($1 < $firsttime) {
+				$firsttime = $1;
+			}
+		}
+		$count = $count + 1;
+	}
+
+	# Find end of init calls as instrumented in UBoot with DO_INITCALLXXX macros
+	if ($line =~ /([0-9\.]+)\] initcall (0x[a-zA-Z0-9\_\.]+).*returned/) {
+		if ($done == 0) {
+			my $func = sprintf("%x", (hex($2) - $reloffset + $textoffset));
+			$func = $sym{$func};
+			$end{$func} = $1;
+			$maxtime = $1;
+		}
+	}
+
+	# Determine where UBoot relocates itself in RAM
+	if ($line =~ /performing relocate to ram to (0x[a-zA-Z0-9\_\.]+)/) {
+		$reloffset = hex($1);
+	}
+	
+	# Stop scanning once we've left UBoot
+	if ($line =~ /Starting kernel /) {
+		$done = 1;
+	}
+}
+
+# No data was captured
+if ($count == 0) {
+    print STDERR <<END;
+No data found in the dmesg. Make sure that CONFIG_BOOT_TRACE is
+defined. 
+Usage:
+      cat uboot.trace | perl ./tools/bootgraph.pl > output.svg
+END
+    exit 1;
+}
+
+print "<?xml version=\"1.0\" standalone=\"no\"?> \n";
+print "<svg width=\"2000\" height=\"100%\" version=\"1.1\" xmlns=\"http://www.w3.org/2000/svg\">\n";
+
+my @styles;
+
+$styles[0] = "fill:rgb(0,0,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[1] = "fill:rgb(0,255,0);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[2] = "fill:rgb(255,0,20);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[3] = "fill:rgb(255,255,20);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[4] = "fill:rgb(255,0,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[5] = "fill:rgb(0,255,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[6] = "fill:rgb(0,128,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[7] = "fill:rgb(0,255,128);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[8] = "fill:rgb(255,0,128);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[9] = "fill:rgb(255,255,128);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[10] = "fill:rgb(255,128,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[11] = "fill:rgb(128,255,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+
+my $style_wait = "fill:rgb(128,128,128);fill-opacity:0.5;stroke-width:0;stroke:rgb(0,0,0)";
+
+my $mult = 1950.0 / ($maxtime - $firsttime);
+my $threshold2 = ($maxtime - $firsttime) / 120.0;
+my $threshold = $threshold2/10;
+my $stylecounter = 0;
+my @initcalls = sort { $start{$a} <=> $start{$b} } keys(%start);
+
+foreach my $key (@initcalls) {
+	my $duration = $end{$key} - $start{$key};
+
+	if ($duration >= $threshold) {
+		my ($s, $s2, $s3, $e, $w, $y, $y2, $style);
+
+		$s = ($start{$key} - $firsttime) * $mult;
+		$s2 = $s + 6;
+		$s3 = $s + 1;
+		$e = ($end{$key} - $firsttime) * $mult;
+		$w = $e - $s;
+
+		$y = 150;
+		$y2 = $y + 4;
+
+		$style = $styles[$stylecounter];
+		$stylecounter = $stylecounter + 1;
+		if ($stylecounter > 11) {
+			$stylecounter = 0;
+		};
+
+		if ($type{$key} == 1) {
+			$y = $y + 15;
+			print "<rect x=\"$s\" width=\"$w\" y=\"$y\" height=\"115\" style=\"$style_wait\"/>\n";
+		} else {
+			print "<rect x=\"$s\" width=\"$w\" y=\"$y\" height=\"145\" style=\"$style\"/>\n";
+			if ($duration >= $threshold2) {
+				print "<text transform=\"translate($s2,$y2) rotate(90)\">$key</text>\n";
+			} else {
+				print "<text transform=\"translate($s3,$y2) rotate(90)\" font-size=\"3pt\">$key</text>\n";
+			}
+		}
+	}
+}
+
+
+# print the time line on top
+my $time = $firsttime;
+my $step = ($maxtime - $firsttime) / 15;
+while ($time < $maxtime) {
+	my $s3 = ($time - $firsttime) * $mult;
+	my $tm = int($time * 100) / 100.0;
+	print "<text transform=\"translate($s3,89) rotate(90)\">$tm</text>\n";
+	$time = $time + $step;
+}
+
+print "</svg>\n";
Signature · 1 line
1.7.4.1
author
#2 lore raw

PATCH 2/7 Add macros for recording init calls during UBoot execution

In reply to Andrew Murray

From: Andrew Murray <[email protected]>

This patch adds macros which allow for the instrumentation of UBoot boot time. The macros can be used to call existing initialisation functions during start up. Each macro adds printf statements before and after the initialisation call.

Signed-off-by Andrew Murray <[email protected]>
---
 include/common.h |   23 +++++++++++++++++++++++
 1 files changed, 23 insertions(+), 0 deletions(-)
include/common.h +23 -0
index 1e21b7a..aa21b10 100644
@@ -176,6 +176,29 @@ typedef void (interrupt_handler_t)(void *);
 
 #endif /* CONFIG_SERIAL_MULTI */
 
+#if defined(CONFIG_BOOT_TRACE)
+#define DO_INITCALL(x, ...) \
+	do { \
+		printf("calling  0x%pF\n", x); \
+		(x)(__VA_ARGS__); \
+		printf("initcall 0x%pF returned\n", x); \
+	} while (0)
+#define DO_INITCALL_RET(x, ret, ...) \
+	do { \
+		printf("calling  0x%pF\n", x); \
+		ret = (x)(__VA_ARGS__); \
+		printf("initcall 0x%pF returned\n", x); \
+	} while (0)
+#define DO_INITCALL_END(x) \
+	printf("initcall 0x%pF returned\n", x)
+#else
+#define DO_INITCALL(x, ...) \
+	(x)(__VA_ARGS__)
+#define DO_INITCALL_RET(x, ret, ...) \
+	ret = (x)(__VA_ARGS__)
+#define DO_INITCALL_END(x)
+#endif
+
 /*
  * General Purpose Utilities
  */
Signature · 1 line
1.7.4.1
#3 lore raw

PATCH 2/7 Add macros for recording init calls during UBoot execution

include/common.h typedef void (interrupt_handler_t)(void *); · line 185

Quoted 7 lines · On Wednesday, August 31, 2011 18:20:56 Andrew Murray wrote:
include/common.h +7 -0
+#if defined(CONFIG_BOOT_TRACE)
+#define DO_INITCALL(x, ...) \
+	do { \
+		printf("calling  0x%pF\n", x); \
+		(x)(__VA_ARGS__); \
+		printf("initcall 0x%pF returned\n", x); \
+	} while (0)

are there any void initcalls ? or just ones where you ignore the value ? otherwise we can simply rename DO_INITCALL_RET() to DO_INITCALL().

include/common.h typedef void (interrupt_handler_t)(void *); · line 191

Quoted 6 lines
include/common.h +6 -0
+#define DO_INITCALL_RET(x, ret, ...) \
+	do { \
+		printf("calling  0x%pF\n", x); \
+		ret = (x)(__VA_ARGS__); \
+		printf("initcall 0x%pF returned\n", x); \
+	} while (0)

#define DO_INITCALL_RET(x, ...) \
	({ \
		int __ret; \
		printf("calling  0x%pF\n", x); \
		__ret = (x)(__VA_ARGS__); \
		printf("initcall 0x%pF returned\n", x); \
		__ret; \
	})

-mike
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 836 bytes
Desc: This is a digitally signed message part.
Url : http://lists.denx.de/pipermail/u-boot/attachments/20110831/61532e77/attachment.pgp

author
#4 lore raw

PATCH 2/7 Add macros for recording init calls during UBoot execution

Quoted 11 lines · Mike Frysinger

Review

Quoted 7 lines · On Wednesday, August 31, 2011 18:20:56 Andrew Murray wrote:
(quoted diff) +7 -0
+#if defined(CONFIG_BOOT_TRACE)
+#define DO_INITCALL(x, ...) \
+ ? ? do { \
+ ? ? ? ? ? ? printf("calling ?0x%pF\n", x); \
+ ? ? ? ? ? ? (x)(__VA_ARGS__); \
+ ? ? ? ? ? ? printf("initcall 0x%pF returned\n", x); \
+ ? ? } while (0)

are there any void initcalls ? ?or just ones where you ignore the value ? otherwise we can simply rename DO_INITCALL_RET() to DO_INITCALL().

I guess it depends what you define as an initcall. A lot of functions called during startup (e.g. arch/arm/lib/board.c) return int and in most cases that value is ignored - but there are occasions where void is returned - e.g. env_relocate.

For simplicity you could limit the use cases for this macro to those which just return int and take your proposed approach?

Andrew Murray

author
#5 lore raw

PATCH 3/7 Add timing information to printf's for use with bootgraph.pl

In reply to Andrew Murray

From: Andrew Murray <[email protected]>

This patch adds timings information to printfs.

Signed-off-by Andrew Murray <[email protected]>
---
 common/console.c |   12 +++++++++++-
 1 files changed, 11 insertions(+), 1 deletions(-)
common/console.c +11 -1
index 8c650e0..33de3fa 100644
@@ -370,13 +370,23 @@ int printf(const char *fmt, ...)
 	va_list args;
 	uint i;
 	char printbuffer[CONFIG_SYS_PBSIZE];
+	char *buf = printbuffer;
 
 	va_start(args, fmt);
 
+#if defined(CONFIG_BOOT_TRACE)
+	unsigned long long ticks = get_ticks();
+	int secs = ticks / get_tbclk();
+	int msec = ((ticks * 1000000) / get_tbclk()) - (secs * 1000000);
+
+	i += sprintf(buf, "[%5lu.%06lu] ", secs, msec);
+	buf += i;
+#endif
+
 	/* For this to work, printbuffer must be larger than
 	 * anything we ever want to print.
 	 */
-	i = vsprintf(printbuffer, fmt, args);
+	i += vsprintf(buf, fmt, args);
 	va_end(args);
 
 	/* Print the string */
Signature · 1 line
1.7.4.1
#6 lore raw

PATCH 3/7 Add timing information to printf's for use with bootgraph.pl

Quoted 12 lines · On Wednesday, August 31, 2011 18:20:57 Andrew Murray wrote:
common/console.c +6 -0
 	va_list args;
 	uint i;
 	char printbuffer[CONFIG_SYS_PBSIZE];
+	char *buf = printbuffer;
 
 	va_start(args, fmt);
 
+#if defined(CONFIG_BOOT_TRACE)
+	unsigned long long ticks = get_ticks();
+	int secs = ticks / get_tbclk();
+	int msec = ((ticks * 1000000) / get_tbclk()) - (secs * 1000000);
+

common/console.c int printf(const char *fmt, ...) · line 390

Quoted 10 lines
common/console.c +5 -1
+	i += sprintf(buf, "[%5lu.%06lu] ", secs, msec);
+	buf += i;
+#endif
+
 	/* For this to work, printbuffer must be larger than
 	 * anything we ever want to print.
 	 */
-	i = vsprintf(printbuffer, fmt, args);
+	i += vsprintf(buf, fmt, args);
 	va_end(args);

NAK for a few reasons:
- i dont see how this could possibly compile warning free
- you never initialize "i", only added to it
- you call va_start() inbetween variable decls
-mike
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 836 bytes
Desc: This is a digitally signed message part.
Url : http://lists.denx.de/pipermail/u-boot/attachments/20110831/cbac9de1/attachment.pgp

author
#7 lore raw

PATCH 3/7 Add timing information to printf's for use with bootgraph.pl

Quoted 21 lines · Mike Frysinger
Quoted 20 lines · On Wednesday, August 31, 2011 18:20:57 Andrew Murray wrote:

? ? ? va_list args;
? ? ? uint i;
? ? ? char printbuffer[CONFIG_SYS_PBSIZE];
+ ? ? char *buf = printbuffer;

? ? ? va_start(args, fmt);

(quoted diff) +9 -0
+#if defined(CONFIG_BOOT_TRACE)
+ ? ? unsigned long long ticks = get_ticks();
+ ? ? int secs = ticks / get_tbclk();
+ ? ? int msec = ((ticks * 1000000) / get_tbclk()) - (secs * 1000000);
+
+ ? ? i += sprintf(buf, "[%5lu.%06lu] ", secs, msec);
+ ? ? buf += i;
+#endif
+

? ? ? /* For this to work, printbuffer must be larger than ? ? ? ?* anything we ever want to print.
? ? ? ?*/
- ? ? i = vsprintf(printbuffer, fmt, args);

Quoted 9 lines
Quoted 2 lines

+ ? ? i += vsprintf(buf, fmt, args);
? ? ? va_end(args);

NAK for a few reasons:
?- i dont see how this could possibly compile warning free ?- you never initialize "i", only added to it
?- you call va_start() inbetween variable decls -mike

Yes this does look dreadful - I'll update the patch pending outcome of thread with Simon Glass and existing work in this area.

Andrew Murray

#8 lore raw

PATCH 3/7 Add timing information to printf's for use with bootgraph.pl

In reply to Mike Frysinger

Hi Mike, Andrew,

Quoted 20 lines · Mike Frysinger
Quoted 19 lines · On Wednesday, August 31, 2011 18:20:57 Andrew Murray wrote:
      va_list args;
      uint i;
      char printbuffer[CONFIG_SYS_PBSIZE];
common/console.c +10 -0
+     char *buf = printbuffer;
 
      va_start(args, fmt);
 
+#if defined(CONFIG_BOOT_TRACE)
+     unsigned long long ticks = get_ticks();
+     int secs = ticks / get_tbclk();
+     int msec = ((ticks * 1000000) / get_tbclk()) - (secs * 1000000);
+
+     i += sprintf(buf, "[%5lu.%06lu] ", secs, msec);
+     buf += i;
+#endif
+
      /* For this to work, printbuffer must be larger than
       * anything we ever want to print.
       */
Quoted 8 lines

common/console.c int printf(const char *fmt, ...) · line 390

Quoted 3 lines
common/console.c +1 -1
-     i = vsprintf(printbuffer, fmt, args);
+     i += vsprintf(buf, fmt, args);
      va_end(args);

NAK for a few reasons:
- i dont see how this could possibly compile warning free
- you never initialize "i", only added to it
- you call va_start() inbetween variable decls

And correct me if I'm wrong, but EVERY printf() will get the timing info tacked on - Even the ones without \n which are intermediate prints in larger messages which is going to lead to very ugly outputs

I think instead we should look at another 'printf() with timestamp' function which can be used on an as-needed basis

Regards,

Graeme

author
#9 lore raw

PATCH 3/7 Add timing information to printf's for use with bootgraph.pl

Quoted 32 lines · Graeme Russ

Hi Mike, Andrew,

Quoted 20 lines · Mike Frysinger
Quoted 19 lines · On Wednesday, August 31, 2011 18:20:57 Andrew Murray wrote:

? ? ? va_list args;
? ? ? uint i;
? ? ? char printbuffer[CONFIG_SYS_PBSIZE];
+ ? ? char *buf = printbuffer;

? ? ? va_start(args, fmt);

(quoted diff) +9 -0
+#if defined(CONFIG_BOOT_TRACE)
+ ? ? unsigned long long ticks = get_ticks();
+ ? ? int secs = ticks / get_tbclk();
+ ? ? int msec = ((ticks * 1000000) / get_tbclk()) - (secs * 1000000);
+
+ ? ? i += sprintf(buf, "[%5lu.%06lu] ", secs, msec);
+ ? ? buf += i;
+#endif
+

? ? ? /* For this to work, printbuffer must be larger than ? ? ? ?* anything we ever want to print.
? ? ? ?*/

Quoted 8 lines
Quoted 3 lines

- ? ? i = vsprintf(printbuffer, fmt, args);
+ ? ? i += vsprintf(buf, fmt, args);
? ? ? va_end(args);

NAK for a few reasons:
?- i dont see how this could possibly compile warning free ?- you never initialize "i", only added to it
?- you call va_start() inbetween variable decls

Quoted 6 lines

And correct me if I'm wrong, but EVERY printf() will get the timing info tacked on - Even the ones without \n which are intermediate prints in larger messages which is going to lead to very ugly outputs

I think instead we should look at another 'printf() with timestamp' function which can be used on an as-needed basis

Yes that's exactly the case ... e.g.

[    3.122000] initcall 0x9ff864cc returned
[    3.126000] calling  0x9ff78174
[    3.129000] ## Booting kernel from Legacy Image at 82000000 ...
[    3.135000]    Image Name:   Angstrom/2.6.32/beagleboard
[    3.141000]    Image Type:   [    3.143000] ARM Linux Kernel Image
(uncompressed)
[    3.148000]    Data Size:    [    3.151000] 3194192 Bytes = [

3.154000] 3[ 3.155000]
MiB

It's certainty ugly. A dedicated printf seems very sensible.

Andrew Murray

#10 lore raw

PATCH 3/7 Add timing information to printf's for use with bootgraph.pl

In reply to Mike Frysinger

Dear Mike Frysinger,

Quoted 5 lines · In message <[email protected]> you wrote:

NAK for a few reasons:
- i dont see how this could possibly compile warning free
- you never initialize "i", only added to it
- you call va_start() inbetween variable decls

Could you _please_ accustom yourself to updating the status in patchwork to "changes requested" when sending revierw comments like here?

I think I asked this a couple of times before...

Best regards,

Wolfgang Denk

Signature · 7 lines
DENX Software Engineering GmbH,     MD: Wolfgang Denk & Detlev Zundel
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany
Phone: (+49)-8142-66989-10 Fax: (+49)-8142-66989-80 Email: wd at denx.de
: 1.  What is the possibility of this being added in the future?
In the near future, the probability is close to zero. In the  distant
future, I'll be dead, and posterity can do whatever they like... :-)
                                                              - lwall
#11 lore raw

PATCH 3/7 Add timing information to printf's for use with bootgraph.pl

Quoted 9 lines · On Wednesday, September 07, 2011 17:10:03 Wolfgang Denk wrote:
Quoted 4 lines · Mike Frysinger

NAK for a few reasons:
- i dont see how this could possibly compile warning free
- you never initialize "i", only added to it
- you call va_start() inbetween variable decls

Could you _please_ accustom yourself to updating the status in patchwork to "changes requested" when sending revierw comments like here?

be nice if patchwork itself would key off a tag we could use in our e-mails and auto set the status ...
-mike
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 836 bytes
Desc: This is a digitally signed message part.
Url : http://lists.denx.de/pipermail/u-boot/attachments/20110908/6d7f6782/attachment.pgp

#12 lore raw

PATCH 3/7 Add timing information to printf's for use with bootgraph.pl

Dear Mike Frysinger,

Quoted 7 lines · In message <[email protected]> you wrote:
Quoted 4 lines

Could you _please_ accustom yourself to updating the status in patchwork to "changes requested" when sending revierw comments like here?

be nice if patchwork itself would key off a tag we could use in our e-mails and auto set the status ...

Patchwork offers sufficient features to do this; you just have to use the right tools.

For example, I am using exmh as MUA; this is MH based (well, actuallny nmh these days) and has the nice feature that each message is a separate file, so I can easily run any standard tools on a specific message. I have added a custom button to exmh which will run the command

pw_update 'Changes Requested' $file

with $file holding the file name of the current message.

Script pw_update looks about like this:

---------------------------------------------------------
#!/bin/bash -e

# pwparser.py reads from stdin
hash=$(/home/wd/bin/pwparser.py --hash) <$2
pwclient update -s $1 -h $hash
---------------------------------------------------------

(pwparser.py coming from git/patchwork/apps/patchwork/parser.py)

Feel free to adapt to your favorite MUA...

Best regards,

Wolfgang Denk

Signature · 5 lines
DENX Software Engineering GmbH,     MD: Wolfgang Denk & Detlev Zundel
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany
Phone: (+49)-8142-66989-10 Fax: (+49)-8142-66989-80 Email: [email protected]
Die Scheu vor Verantwortung ist die Krankheit unserer Zeit.
                                                 -- Otto von Bismarck
author
#13 lore raw

PATCH 4/7 Add bootgraph instrumentation for ARM boards

In reply to Andrew Murray

From: Andrew Murray <[email protected]>

This patch adds bootgraph instrumentation for ARM boards.

Signed-off-by Andrew Murray <[email protected]>
---
 arch/arm/lib/board.c |   28 +++++++++++++++++++---------
 1 files changed, 19 insertions(+), 9 deletions(-)
arch/arm/lib/board.c +19 -9
index 169dfeb..e6bb8e2 100644
@@ -271,6 +271,7 @@ void board_init_f (ulong bootflag)
 	init_fnc_t **init_fnc_ptr;
 	gd_t *id;
 	ulong addr, addr_sp;
+	int ret;
 
 	/* Pointer is writable since we allocated a register for it */
 	gd = (gd_t *) ((CONFIG_SYS_INIT_SP_ADDR) & ~0x07);

@@ -282,7 +283,8 @@ void board_init_f (ulong bootflag)
 	gd->mon_len = _bss_end_ofs;
 
 	for (init_fnc_ptr = init_sequence; *init_fnc_ptr; ++init_fnc_ptr) {
-		if ((*init_fnc_ptr)() != 0) {
+		DO_INITCALL_RET(*init_fnc_ptr, ret);
+		if (ret != 0) {
 			hang ();
 		}
 	}

@@ -416,6 +418,9 @@ void board_init_f (ulong bootflag)
 	debug ("relocation Offset is: %08lx\n", gd->reloc_off);
 	memcpy (id, (void *)gd, sizeof (gd_t));
 
+#if defined(CONFIG_BOOT_TRACE)
+	printf("performing relocate to ram to 0x%pF\n", addr);
+#endif
 	relocate_code (addr_sp, id, addr);
 
 	/* NOTREACHED - relocate_code() does not return */

@@ -444,6 +449,10 @@ void board_init_r (gd_t *id, ulong dest_addr)
 	ulong flash_size;
 #endif
 
+#if defined(CONFIG_BOOT_TRACE)
+	printf("completed relocate to ram\n");
+#endif
+
 	gd = id;
 	bd = gd->bd;
 

@@ -451,7 +460,8 @@ void board_init_r (gd_t *id, ulong dest_addr)
 
 	monitor_flash_len = _end_ofs;
 	debug ("monitor flash len: %08lX\n", monitor_flash_len);
-	board_init();	/* Setup chipselects */
+
+	DO_INITCALL(board_init);	/* Setup chipselects */
 
 #ifdef CONFIG_SERIAL_MULTI
 	serial_initialize();

@@ -499,7 +509,7 @@ void board_init_r (gd_t *id, ulong dest_addr)
 
 #if defined(CONFIG_CMD_NAND)
 	puts ("NAND:  ");
-	nand_init();		/* go init the NAND */
+	DO_INITCALL(nand_init);		/* go init the NAND */
 #endif
 
 #if defined(CONFIG_CMD_ONENAND)

@@ -508,7 +518,7 @@ void board_init_r (gd_t *id, ulong dest_addr)
 
 #ifdef CONFIG_GENERIC_MMC
        puts("MMC:   ");
-       mmc_initialize(bd);
+       DO_INITCALL(mmc_initialize, bd);
 #endif
 
 #ifdef CONFIG_HAS_DATAFLASH

@@ -517,7 +527,7 @@ void board_init_r (gd_t *id, ulong dest_addr)
 #endif
 
 	/* initialize environment */
-	env_relocate ();
+	DO_INITCALL(env_relocate);
 
 #if defined(CONFIG_CMD_PCI) || defined(CONFIG_PCI)
 	arm_pci_init();

@@ -526,16 +536,16 @@ void board_init_r (gd_t *id, ulong dest_addr)
 	/* IP Address */
 	gd->bd->bi_ip_addr = getenv_IPaddr ("ipaddr");
 
-	stdio_init ();	/* get the devices list going. */
+	DO_INITCALL(stdio_init);	/* get the devices list going. */
 
-	jumptable_init ();
+	DO_INITCALL(jumptable_init);
 
 #if defined(CONFIG_API)
 	/* Initialize API */
 	api_init ();
 #endif
 
-	console_init_r ();	/* fully init console as a device */
+	DO_INITCALL(console_init_r);	/* fully init console as a device */
 
 #if defined(CONFIG_ARCH_MISC_INIT)
 	/* miscellaneous arch dependent initialisations */

@@ -543,7 +553,7 @@ void board_init_r (gd_t *id, ulong dest_addr)
 #endif
 #if defined(CONFIG_MISC_INIT_R)
 	/* miscellaneous platform dependent initialisations */
-	misc_init_r ();
+	DO_INITCALL(misc_init_r);
 #endif
 
 	 /* set up exceptions */
Signature · 1 line
1.7.4.1
author
#14 lore raw

PATCH 5/7 Add bootgraph instrumentation for bootm command

In reply to Andrew Murray

Under normal operation the bootm command will never return - this patch adds additional instrumentation to signal the 'end' of the bootm command such that this point can be reflected in any bootgraph SVG.

Signed-off-by Andrew Murray <[email protected]>
---
 common/cmd_bootm.c |    1 +
 1 files changed, 1 insertions(+), 0 deletions(-)
common/cmd_bootm.c +1 -0
index 1966da4..147e8de 100644
@@ -697,6 +697,7 @@ int do_bootm (cmd_tbl_t *cmdtp, int flag, int argc, char * const argv[])
 
 	arch_preboot_os();
 
+	DO_INITCALL_END(do_bootm);
 	boot_fn(0, argc, argv, &images);
 
 	show_boot_progress (-9);
Signature · 1 line
1.7.4.1
author
#15 lore raw

PATCH 6/7 Add bootgraph instrumentation for UBoot commands

In reply to Andrew Murray

From: Andrew Murray <[email protected]>

This patch adds bootgraph instrumentation for all U_BOOT_CMDs where the HUSH parser is not used. The patch also adds instrumentation for the common boot delay.

Signed-off-by Andrew Murray <[email protected]>
---
 common/main.c |   19 ++++++++++++-------
 1 files changed, 12 insertions(+), 7 deletions(-)
common/main.c +12 -7
index 2730c6f..0c78a94 100644
@@ -273,6 +273,7 @@ void main_loop (void)
 	int rc = 1;
 	int flag;
 #endif
+	int ret;
 
 #if defined(CONFIG_BOOTDELAY) && (CONFIG_BOOTDELAY >= 0)
 	char *s;

@@ -376,21 +377,24 @@ void main_loop (void)
 
 	debug ("### main_loop: bootcmd=\"%s\"\n", s ? s : "<UNDEFINED>");
 
-	if (bootdelay >= 0 && s && !abortboot (bootdelay)) {
+	if (bootdelay >= 0 && s) {
+		DO_INITCALL_RET(abortboot, ret, bootdelay);
+		if (!ret) {
 # ifdef CONFIG_AUTOBOOT_KEYED
-		int prev = disable_ctrlc(1);	/* disable Control C checking */
+			int prev = disable_ctrlc(1);	/* disable Control C checking */
 # endif
 
 # ifndef CONFIG_SYS_HUSH_PARSER
-		run_command (s, 0);
+			run_command (s, 0);
 # else
-		parse_string_outer(s, FLAG_PARSE_SEMICOLON |
+			parse_string_outer(s, FLAG_PARSE_SEMICOLON |
 				    FLAG_EXIT_FROM_LOOP);
 # endif
 
 # ifdef CONFIG_AUTOBOOT_KEYED
-		disable_ctrlc(prev);	/* restore Control C checking */
+			disable_ctrlc(prev);	/* restore Control C checking */
 # endif
+		}
 	}
 
 # ifdef CONFIG_MENUKEY

@@ -1271,7 +1275,7 @@ int run_command (const char *cmd, int flag)
 	char *argv[CONFIG_SYS_MAXARGS + 1];	/* NULL terminated	*/
 	int argc, inquotes;
 	int repeatable = 1;
-	int rc = 0;
+	int rc = 0, ret;
 
 #ifdef DEBUG_PARSER
 	printf ("[RUN_COMMAND] cmd[%p]=\"", cmd);

@@ -1371,7 +1375,8 @@ int run_command (const char *cmd, int flag)
 #endif
 
 		/* OK - call function to do the command */
-		if ((cmdtp->cmd) (cmdtp, flag, argc, argv) != 0) {
+		DO_INITCALL_RET(cmdtp->cmd, ret, cmdtp, flag, argc, argv);
+		if (ret != 0) {
 			rc = -1;
 		}
Signature · 1 line
1.7.4.1
author
#16 lore raw

PATCH 7/7 Add documentation for bootgraph.pl

In reply to Andrew Murray

From: Andrew Murray <[email protected]>

Documentation for the CONFIG_BOOT_TRACE option.

Signed-off-by Andrew Murray <[email protected]>
---
 doc/README.bootgraph |   57 ++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 57 insertions(+), 0 deletions(-)
 create mode 100644 doc/README.bootgraph
doc/README.bootgraph new file +57 -0
new file mode 100644
index 0000000..af8d9e4
@@ -0,0 +1,57 @@
+Bootgraph Instrumentation
+-------------------------
+
+The CONFIG_BOOT_TRACE configuration option can be defined to output extensive
+instrumentation to assist in boot time reduction. The tools/bootgraph.pl script
+can utilise this instrumentation to generate an SVG graph showing where UBoot
+spends its time.
+
+When enabled all printf output is prefixed with timing information similar
+to the Linux kernel's CONFIG_PRINTK_TIME option. This allows you to measure the
+interval between operations which is useful for identifying long delays during
+UBoot operation. For example:
+
+[    3.133000] ## Booting kernel from Legacy Image at 82000000 ...
+[    3.139000]    Image Name:   Angstrom/2.6.32/beagleboard
+
+When enabled additional console output will be generated - this output includes
+the addresses of executed commands and instrumented functions. For example:
+
+[    2.456000] initcall 0x9ff86814 returned
+[    2.460000] calling  0x9ff7c338
+[    2.590000] initcall 0x9ff7c338 returned
+[    2.594000] calling  0x9ff864ac
+
+At present executed commands are only displayed when the HUSH parser
+(CONFIG_SYS_HUSH_PARSER) is not being used.
+
+Functions such as initialisation code can be instrumented by using the
+DO_INITCALLXXX macros found in include/common.h (see arch/arm/lib/board.c) for
+examples). For example:
+
+@@ -508,7 +518,7 @@ void board_init_r (gd_t *id, ulong dest_addr)
+
+ #ifdef CONFIG_GENERIC_MMC
+        puts("MMC:   ");
+-       mmc_initialize(bd);
++       DO_INITCALL(mmc_initialize, bd);
+ #endif
+
+For functions that do not return such as do_bootm function, the DO_INITCALL_END
+macro can be used to mark the latest point of the function.
+
+When CONFIG_BOOT_TIME is not defined the DO_INITCALLXXX macros continue to call
+the intended function and should not add overhead.
+
+An SVG graph can be generated which allows for the visualisation of UBoot boot
+time by using the tools/bootgraph.pl script. This script has been ported from
+the Linux kernel (scripts/bootgraph.pl) and is used in a similar way. For
+example:
+
+cat console_output | perl ./tools/bootgraph.pl > graph.svg
+
+Assuming console_output is a file containing the console output of UBoot with
+CONFIG_BOOT_TRACE enabled - the graph.svg file should provide a graphical
+representation of boot time with resolved function addresses.
+
+Andrew Murray <[email protected]>
Signature · 1 line
1.7.4.1
#17 lore raw

cover Bootgraph.pl instrumentation support for UBoot

In reply to Andrew Murray
Quoted 13 lines · On Wednesday, August 31, 2011 18:20:54 Andrew Murray wrote:

This patchset introduces the CONFIG_BOOT_TRACE option which provides support for boot time instrumentation.

When enabled printf output is prefixed with timing information (similar to the kernel's CONFIG_PRINTK_TIME option) and additional output is generated which instruments functions and commands called (much like the kernel's initcall_debug functionality).

The kernel's bootgraph.pl script has been ported to render UBoots instrumented ouptut into a pretty SVG graph. An example of this can be found here: http://goo.gl/dX8aR - which shows the boot time of a Beagle board.

Quoted 5 lines

The patch currently provides support for instrumentation of UBoot commands (e.g. U_BOOT_CMD) for all platforms but only when the HUSH shell is not in use. Initialisation instrumentation is only limited to the arch/arm/lib/board.c file at present but can very easily be extended to other relevant files.

i feel like we've had similar ideas tossed around semi-recently. am i just misremembering ?
-mike
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 836 bytes
Desc: This is a digitally signed message part.
Url : http://lists.denx.de/pipermail/u-boot/attachments/20110831/44c7e27b/attachment.pgp

#18 lore raw

cover Bootgraph.pl instrumentation support for UBoot

Hi Mike,

Quoted 20 lines · Mike Frysinger
Quoted 13 lines · On Wednesday, August 31, 2011 18:20:54 Andrew Murray wrote:

This patchset introduces the CONFIG_BOOT_TRACE option which provides support for boot time instrumentation.

When enabled printf output is prefixed with timing information (similar to the kernel's CONFIG_PRINTK_TIME option) and additional output is generated which instruments functions and commands called (much like the kernel's initcall_debug functionality).

The kernel's bootgraph.pl script has been ported to render UBoots instrumented ouptut into a pretty SVG graph. An example of this can be found here: http://goo.gl/dX8aR - which shows the boot time of a Beagle board.

Quoted 5 lines

The patch currently provides support for instrumentation of UBoot commands (e.g. U_BOOT_CMD) for all platforms but only when the HUSH shell is not in use. Initialisation instrumentation is only limited to the arch/arm/lib/board.c file at present but can very easily be extended to other relevant files.

Quoted 4 lines

i feel like we've had similar ideas tossed around semi-recently. ?am i just misremembering ?
-mike

Yes, for example:

http://patchwork.ozlabs.org/patch/95513/

It got caught up with a big discussion about whether we want a microsecond timer. There is now one in Tegra, but not in the generic timer API. There was also a request to unify this with the boot_progress stuff (i.e. it turned into a big cleanup).

I haven't got back to it yet, but could probably do something next week.

I also have patches to pass the timings to the kernel and have it report them to user space through a device. Planning to send an RFC to the LKML about that probably next week as well. Could be fun.

Regards,
Simon

#19 lore raw

cover Bootgraph.pl instrumentation support for UBoot

Quoted 37 lines · Simon Glass

Hi Mike,

Quoted 20 lines · Mike Frysinger
Quoted 13 lines · On Wednesday, August 31, 2011 18:20:54 Andrew Murray wrote:

This patchset introduces the CONFIG_BOOT_TRACE option which provides support for boot time instrumentation.

When enabled printf output is prefixed with timing information (similar to the kernel's CONFIG_PRINTK_TIME option) and additional output is generated which instruments functions and commands called (much like the kernel's initcall_debug functionality).

The kernel's bootgraph.pl script has been ported to render UBoots instrumented ouptut into a pretty SVG graph. An example of this can be found here: http://goo.gl/dX8aR - which shows the boot time of a Beagle board.

Quoted 5 lines

The patch currently provides support for instrumentation of UBoot commands (e.g. U_BOOT_CMD) for all platforms but only when the HUSH shell is not in use. Initialisation instrumentation is only limited to the arch/arm/lib/board.c file at present but can very easily be extended to other relevant files.

Quoted 4 lines

i feel like we've had similar ideas tossed around semi-recently. ?am i just misremembering ?
-mike

Yes, for example:

http://patchwork.ozlabs.org/patch/95513/

It got caught up with a big discussion about whether we want a microsecond timer. There is now one in Tegra, but not in the generic timer API. There was also a request to unify this with the boot_progress stuff (i.e. it turned into a big cleanup).

Quoted 9 lines

I haven't got back to it yet, but could probably do something next week.

I also have patches to pass the timings to the kernel and have it report them to user space through a device. Planning to send an RFC to the LKML about that probably next week as well. Could be fun.

Regards,
Simon

Ah - my bad. I only subscribed to the mailing list today (my first UBoot patch) and didn't notice this previous work.

Is there any cross over between my approach and what is planned/already been done?

Andrew Murray

#20 lore raw

cover Bootgraph.pl instrumentation support for UBoot

Hi Andrew,

Quoted 8 lines · Andrew Murray
Quoted 7 lines · Simon Glass

Hi Mike,

Quoted 4 lines · Mike Frysinger
Quoted 3 lines · On Wednesday, August 31, 2011 18:20:54 Andrew Murray wrote:

This patchset introduces the CONFIG_BOOT_TRACE option which provides support for boot time instrumentation.

[snip]

Quoted 9 lines
Quoted 9 lines
Quoted 9 lines
Quoted 6 lines

The patch currently provides support for instrumentation of UBoot commands (e.g. U_BOOT_CMD) for all platforms but only when the HUSH shell is not in use. Initialisation instrumentation is only limited to the arch/arm/lib/board.c file at present but can very easily be extended to other relevant files.

i feel like we've had similar ideas tossed around semi-recently. am i just misremembering ?

No, your memory is fine :)

Quoted 22 lines
Quoted 12 lines
Quoted 2 lines

-mike

Yes, for example:

http://patchwork.ozlabs.org/patch/95513/

It got caught up with a big discussion about whether we want a microsecond timer. There is now one in Tegra, but not in the generic timer API. There was also a request to unify this with the boot_progress stuff (i.e. it turned into a big cleanup).

Quoted 9 lines

I haven't got back to it yet, but could probably do something next week.

I also have patches to pass the timings to the kernel and have it report them to user space through a device. Planning to send an RFC to the LKML about that probably next week as well. Could be fun.

Regards,
Simon

Quoted 6 lines

Ah - my bad. I only subscribed to the mailing list today (my first UBoot patch) and didn't notice this previous work.

Is there any cross over between my approach and what is planned/already been done?

Have a look through the mailing list archive - I find this one the easiest for scanning headings: http://lists.denx.de/pipermail/u-boot/

Take a look over the last few months for anything timer related - Trust me, the rabit warren is very deep ;)

When I get a chance to breath again, I'll be taking another look at the timer API and with the (hopefully) pending inclusion of the pre-console buffer, I think boot tracing will come together very nicely

Regards,

Graeme

#21 lore raw

cover Bootgraph.pl instrumentation support for UBoot

Hi Andrew,

Quoted 21 lines · Graeme Russ

Hi Andrew,

Quoted 8 lines · Andrew Murray
Quoted 7 lines · Simon Glass

Hi Mike,

Quoted 4 lines · Mike Frysinger
Quoted 3 lines · On Wednesday, August 31, 2011 18:20:54 Andrew Murray wrote:

This patchset introduces the CONFIG_BOOT_TRACE option which provides support for boot time instrumentation.

[snip]

Quoted 7 lines
Quoted 7 lines
Quoted 7 lines
Quoted 6 lines

The patch currently provides support for instrumentation of UBoot commands (e.g. U_BOOT_CMD) for all platforms but only when the HUSH shell is not in use. Initialisation instrumentation is only limited to the arch/arm/lib/board.c file at present but can very easily be extended to other relevant files.

Quoted 33 lines
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines

i feel like we've had similar ideas tossed around semi-recently. ?am i just misremembering ?

No, your memory is fine :)

Quoted 28 lines
Quoted 12 lines
Quoted 2 lines

-mike

Yes, for example:

http://patchwork.ozlabs.org/patch/95513/

It got caught up with a big discussion about whether we want a microsecond timer. There is now one in Tegra, but not in the generic timer API. There was also a request to unify this with the boot_progress stuff (i.e. it turned into a big cleanup).

Quoted 9 lines

I haven't got back to it yet, but could probably do something next week.

I also have patches to pass the timings to the kernel and have it report them to user space through a device. Planning to send an RFC to the LKML about that probably next week as well. Could be fun.

Regards,
Simon

Ah - my bad. I only subscribed to the mailing list today (my first UBoot patch) and didn't notice this previous work.

Is there any cross over between my approach and what is planned/already been done?

Don't worry - your contribution is very welcome!

Yes I think there is cross-over, and perhaps the right approach is to try to merge them somehow. It is great to get graphs out of the code and it really helps with analysis. My interest was mainly in monitoring boot time in the field rather than in the lab. But we should have one framework for both.

Quoted 7 lines

Have a look through the mailing list archive - I find this one the easiest for scanning headings: http://lists.denx.de/pipermail/u-boot/

Take a look over the last few months for anything timer related - Trust me, the rabit warren is very deep ;)

Please don't look at the mailing list for timer-related things as you will go mad.

Quoted 8 lines

When I get a chance to breath again, I'll be taking another look at the timer API and with the (hopefully) pending inclusion of the pre-console buffer, I think boot tracing will come together very nicely

Regards,

Graeme

I will assume that we have a microsecond timer, update my patch and resubmit so you can take a look and see what you think. Hopefully we can unify this, your patch and the boot_progress stuff.

Regards,
Simon

author
#22 lore raw

cover Bootgraph.pl instrumentation support for UBoot

Quoted 12 lines · Simon Glass
Quoted 4 lines
Quoted 4 lines

Is there any cross over between my approach and what is planned/already been done?

Don't worry - your contribution is very welcome!

Yes I think there is cross-over, and perhaps the right approach is to try to merge them somehow. It is great to get graphs out of the code and it really helps with analysis. My interest was mainly in monitoring boot time in the field rather than in the lab. But we should have one framework for both.

[SNIP]

Quoted 4 lines

I will assume that we have a microsecond timer, update my patch and resubmit so you can take a look and see what you think. Hopefully we can unify this, your patch and the boot_progress stuff.

Excellent! OK, well I will await the patch, read up on the original intentions and we can go from there. I'll look forward to making UBoot more boot time friendly. Good night.

Andrew Murray

author
#23 lore raw

cover Bootgraph.pl instrumentation support for UBoot

Quoted 8 lines · Andrew Murray
Quoted 4 lines

I will assume that we have a microsecond timer, update my patch and resubmit so you can take a look and see what you think. Hopefully we can unify this, your patch and the boot_progress stuff.

Excellent! OK, well I will await the patch, read up on the original intentions and we can go from there. I'll look forward to making UBoot more boot time friendly. Good night.

I've updated my patches based on your feedback. I guess the next step is to see how
to integrate with the bootstage work.

Andrew Murray

#24 lore raw

cover Bootgraph.pl instrumentation support for UBoot

Hi Andrew,

Quoted 7 lines · Andrew Murray
Quoted 6 lines · Andrew Murray
Quoted 5 lines

I will assume that we have a microsecond timer, update my patch and resubmit so you can take a look and see what you think. Hopefully we can unify this, your patch and the boot_progress stuff.

Quoted 8 lines
Quoted 3 lines

Excellent! OK, well I will await the patch, read up on the original intentions and we can go from there. I'll look forward to making UBoot more boot time friendly. Good night.

I've updated my patches based on your feedback. I guess the next step is to see how
to integrate with the bootstage work.
Andrew Murray

Thanks for the patch set. I have a few general comments.

- textbase should come from System.map also - it is hard coded at present
- Perl is ick, but it was good because it reminded me of why I am happier in Python :-)
- Patch 4 didn't apply cleanly on master
- Should add to hush parser also
- Perl script could use some error checking. I had a bit of fun debugging it as it silent failed
- The resulting image was very long and I had to zoom in a lot to see any text. Perhaps increase font size a lot so you can see the timeline and function names?
- You should use do_div for the 64-bit division I think
- I think the mention of CONFIG_BOOT_TIME should be CONFIG_BOOT_TRACE

This patch touches on Graeme's initcall patch. If board_init_r were just a list of function pointers then your patch would be easier! Not much we can do about that at this stage, and I think your solution is reasonable.

Regards,
Simon

#25 lore raw

cover Bootgraph.pl instrumentation support for UBoot

Hi Simon,

Quoted 11 lines · Simon Glass

Hi Andrew,

Quoted 2 lines · Andrew Murray
Quoted 1 line · Andrew Murray

This patch touches on Graeme's initcall patch. If board_init_r were just a list of function pointers then your patch would be easier! Not much we can do about that at this stage, and I think your solution is reasonable.

And I would love to get this back on the table - I honestly think that the initcall solution, although it had it's own set of 'problems' is a more robust approach that the current 'array of function pointers' solution.

I think we now have a number of ideas (some with solid patches) that is going to make the future of the boot sequence very bright indead:

- Bootgraph
- Unified timer API (nanosecond would be nice)
- initcall
- 'pre-console' output buffer
- timestamped printf()

Looking forward to opening up these cans of worms again :)

Regards,

Graeme

#26 lore raw

cover Bootgraph.pl instrumentation support for UBoot

Hi Graeme,

Quoted 15 lines · Graeme Russ

Hi Simon,

Quoted 11 lines · Simon Glass

Hi Andrew,

Quoted 2 lines · Andrew Murray
Quoted 1 line · Andrew Murray

This patch touches on Graeme's initcall patch. If board_init_r were just a list of function pointers then your patch would be easier! Not much we can do about that at this stage, and I think your solution is reasonable.

Quoted 4 lines

And I would love to get this back on the table - I honestly think that the initcall solution, although it had it's own set of 'problems' is a more robust approach that the current 'array of function pointers' solution.

Yes I prefer it, it's a question of how to make things simple and obvious, and not obfuscate to much something which is currently very simple (if a little primitive). With respect to initcalls, it would perhaps be a shorter step if the board_init_f/r functions were truly just running through a list of function pointers. At present they contain other code also.

Also, while we worry about ordering, it is really important that (for example) NAND init happens before MMC?

Quoted 11 lines

I think we now have a number of ideas (some with solid patches) that is going to make the future of the boot sequence very bright indead:

?- Bootgraph
?- Unified timer API (nanosecond would be nice)
?- initcall
?- 'pre-console' output buffer
?- timestamped printf()

Looking forward to opening up these cans of worms again :)

Bravery is to be encouraged. Biting off what seems like the smallest, what is the status of pre-console output?

Regards,
Simon

Quoted 5 lines

Regards,

Graeme

#27 lore raw

cover Bootgraph.pl instrumentation support for UBoot

Hi Simon,

Quoted 11 lines · Simon Glass

Hi Graeme,

Quoted 8 lines · Graeme Russ

Hi Simon,

Quoted 5 lines · Simon Glass

Hi Andrew,

Quoted 2 lines · Andrew Murray
Quoted 1 line · Andrew Murray

[snip]

Quoted 10 lines
Quoted 7 lines

- Bootgraph
- Unified timer API (nanosecond would be nice)
- initcall
- 'pre-console' output buffer
- timestamped printf()

Looking forward to opening up these cans of worms again :)

Bravery is to be encouraged. Biting off what seems like the smallest, what is the status of pre-console output?

I made the requested changes, the pre-console buffer only gets compiled in if it is explicitly configured and it works a treat

I see no reason not to include it (along with the pre-console printf() squelching)

The only related patch that was under discussion was 'flagifying' a couple of global variables which opened up a question regarding the impact on API versioning - Wolfgang resolved this with 'gd does not impact API version' so the 'flagify' patch could also be added to the mix, but that's not really that critical and could come in later after the dust settles.

Unified timer API would be the next 'least contentious' - There is universal agreement on the why, but not on the how. I'll reopen this again 'soon'

The initcall API is the most contentious... Asbestos suit is still on the clothes line drying ;)

Regards,

Graeme

#28 lore raw

cover Bootgraph.pl instrumentation support for UBoot

Hi Graeme,

Quoted 25 lines · Graeme Russ

Hi Simon,

Quoted 11 lines · Simon Glass

Hi Graeme,

Quoted 8 lines · Graeme Russ

Hi Simon,

Quoted 5 lines · Simon Glass

Hi Andrew,

Quoted 2 lines · Andrew Murray
Quoted 1 line · Andrew Murray

[snip]

Quoted 8 lines
Quoted 7 lines

?- Bootgraph
?- Unified timer API (nanosecond would be nice)
?- initcall
?- 'pre-console' output buffer
?- timestamped printf()

Looking forward to opening up these cans of worms again :)

Quoted 8 lines
Quoted 2 lines

Bravery is to be encouraged. Biting off what seems like the smallest, what is the status of pre-console output?

I made the requested changes, the pre-console buffer only gets compiled in if it is explicitly configured and it works a treat

I see no reason not to include it (along with the pre-console printf() squelching)

I agree, it has my vote. I will test it again this week and come back to you.

Quoted 6 lines

The only related patch that was under discussion was 'flagifying' a couple of global variables which opened up a question regarding the impact on API versioning - Wolfgang resolved this with 'gd does not impact API version' so the 'flagify' patch could also be added to the mix, but that's not really that critical and could come in later after the dust settles.

OK yes, I remember, a separate patch then.

Quoted 4 lines

Unified timer API would be the next 'least contentious' - There is universal agreement on the why, but not on the how. I'll reopen this again 'soon'

Good, and good luck

Quoted 3 lines

The initcall API is the most contentious... Asbestos suit is still on the clothes line drying ;)

I'm impressed that you didn't wear that out with the timer stuff. You must have bought a really high quality suit!

Regards,
Simon

Quoted 5 lines

Regards,

Graeme

author
#29 lore raw

PATCH v2 1/7 Add bootgraph.pl script for generating a boot graph SVG file

In reply to Andrew Murray

From: Andrew Murray <[email protected]>

This is a port of the kernel's script/bootgraph.pl script which generates an SVG image illustrating boot time in UBoot. The script relies on additional output generated by UBoot during boot when the CONFIG_BOOT_TRACE option is enabled.

Signed-off-by Andrew Murray <[email protected]>
---
 tools/bootgraph.pl |  189 ++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 189 insertions(+), 0 deletions(-)
 create mode 100755 tools/bootgraph.pl
tools/bootgraph.pl new file +189 -0
new file mode 100755
index 0000000..8b206b5
@@ -0,0 +1,189 @@
+#!/usr/bin/perl
+
+# Copyright (C) 2011, Andrew Murray <[email protected]>)
+# Copyright (C) 2008, Intel Corporation (Arjan van de Ven <[email protected]>)
+#
+# This program file 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; version 2 of the License.
+#
+# 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 in a file named COPYING; if not, write to the
+# Free Software Foundation, Inc.,
+# 51 Franklin Street, Fifth Floor,
+# Boston, MA 02110-1301 USA
+#
+# This script was originally written by Arjan for use with the Linux kernel and
+# subsequently ported across to UBoot by Andrew.
+#
+# This script turns a output trace from UBoot into a SVG graphic that shows 
+# which functions take how much time. You can view SVG graphics with various
+# programs, including Inkscape, The Gimp and Firefox.
+#
+# For this script to work, the UBoot config file needs to be compiled with the
+# CONFIG_BOOT_TRACE configuration option enabled.
+#
+# usage:
+# 	cat uboot.trace | perl ./tools/bootgraph.pl > output.svg
+#
+
+use strict;
+
+my %start;
+my %end;
+my %type;
+my $done = 0;
+my $maxtime = 0;
+my $firsttime = 99999;
+my $count = 0;
+my $textoffset = hex('0x80008000');
+my $reloffset = $textoffset;
+my %sym;
+
+if (!open FILE, "System.map") {
+	print STDERR <<END;
+No map file found "./System.map". Make sure that a file named
+System.map exists in the current working directory.
+Usage:
+      cat uboot.trace | perl ./tools/bootgraph.pl > output.svg
+END
+	exit 1;
+}
+
+# Read in a map file to support in the printing of function names
+while (<FILE>) {
+	my $line = $_;
+	if ($line =~ /([a-zA-Z0-9]+)\ [a-zA-Z] ([a-zA-Z0-0\_\.]+)/) {
+		$sym{$1} = $2; 
+	}
+}
+close FILE;
+
+# Parse lines of UBoot's trace to generate a timeline
+while (<>) {
+	my $line = $_;
+
+	# Find start of init calls as instrumented in UBoot with DO_INITCALLXXX macros
+	if ($line =~ /([0-9\.]+)\] calling  (0x[a-zA-Z0-9\_\.]+)/) {
+		my $func = sprintf("%x", (hex($2) - $reloffset + $textoffset));
+		$func = $sym{$func};
+		if ($done == 0) {
+			$start{$func} = $1;
+			$type{$func} = 0;
+			if ($1 < $firsttime) {
+				$firsttime = $1;
+			}
+		}
+		$count = $count + 1;
+	}
+
+	# Find end of init calls as instrumented in UBoot with DO_INITCALLXXX macros
+	if ($line =~ /([0-9\.]+)\] initcall (0x[a-zA-Z0-9\_\.]+).*returned/) {
+		if ($done == 0) {
+			my $func = sprintf("%x", (hex($2) - $reloffset + $textoffset));
+			$func = $sym{$func};
+			$end{$func} = $1;
+			$maxtime = $1;
+		}
+	}
+
+	# Determine where UBoot relocates itself in RAM
+	if ($line =~ /performing relocate to ram to (0x[a-zA-Z0-9\_\.]+)/) {
+		$reloffset = hex($1);
+	}
+	
+	# Stop scanning once we've left UBoot
+	if ($line =~ /Starting kernel /) {
+		$done = 1;
+	}
+}
+
+# No data was captured
+if ($count == 0) {
+    print STDERR <<END;
+No data found in the dmesg. Make sure that CONFIG_BOOT_TRACE is
+defined. 
+Usage:
+      cat uboot.trace | perl ./tools/bootgraph.pl > output.svg
+END
+    exit 1;
+}
+
+print "<?xml version=\"1.0\" standalone=\"no\"?> \n";
+print "<svg width=\"2000\" height=\"100%\" version=\"1.1\" xmlns=\"http://www.w3.org/2000/svg\">\n";
+
+my @styles;
+
+$styles[0] = "fill:rgb(0,0,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[1] = "fill:rgb(0,255,0);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[2] = "fill:rgb(255,0,20);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[3] = "fill:rgb(255,255,20);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[4] = "fill:rgb(255,0,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[5] = "fill:rgb(0,255,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[6] = "fill:rgb(0,128,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[7] = "fill:rgb(0,255,128);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[8] = "fill:rgb(255,0,128);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[9] = "fill:rgb(255,255,128);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[10] = "fill:rgb(255,128,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+$styles[11] = "fill:rgb(128,255,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
+
+my $style_wait = "fill:rgb(128,128,128);fill-opacity:0.5;stroke-width:0;stroke:rgb(0,0,0)";
+
+my $mult = 1950.0 / ($maxtime - $firsttime);
+my $threshold2 = ($maxtime - $firsttime) / 120.0;
+my $threshold = $threshold2/10;
+my $stylecounter = 0;
+my @initcalls = sort { $start{$a} <=> $start{$b} } keys(%start);
+
+foreach my $key (@initcalls) {
+	my $duration = $end{$key} - $start{$key};
+
+	if ($duration >= $threshold) {
+		my ($s, $s2, $s3, $e, $w, $y, $y2, $style);
+
+		$s = ($start{$key} - $firsttime) * $mult;
+		$s2 = $s + 6;
+		$s3 = $s + 1;
+		$e = ($end{$key} - $firsttime) * $mult;
+		$w = $e - $s;
+
+		$y = 150;
+		$y2 = $y + 4;
+
+		$style = $styles[$stylecounter];
+		$stylecounter = $stylecounter + 1;
+		if ($stylecounter > 11) {
+			$stylecounter = 0;
+		};
+
+		if ($type{$key} == 1) {
+			$y = $y + 15;
+			print "<rect x=\"$s\" width=\"$w\" y=\"$y\" height=\"115\" style=\"$style_wait\"/>\n";
+		} else {
+			print "<rect x=\"$s\" width=\"$w\" y=\"$y\" height=\"145\" style=\"$style\"/>\n";
+			if ($duration >= $threshold2) {
+				print "<text transform=\"translate($s2,$y2) rotate(90)\">$key</text>\n";
+			} else {
+				print "<text transform=\"translate($s3,$y2) rotate(90)\" font-size=\"3pt\">$key</text>\n";
+			}
+		}
+	}
+}
+
+
+# print the time line on top
+my $time = $firsttime;
+my $step = ($maxtime - $firsttime) / 15;
+while ($time < $maxtime) {
+	my $s3 = ($time - $firsttime) * $mult;
+	my $tm = int($time * 100) / 100.0;
+	print "<text transform=\"translate($s3,89) rotate(90)\">$tm</text>\n";
+	$time = $time + $step;
+}
+
+print "</svg>\n";
Signature · 1 line
1.7.4.1
author
#30 lore raw

PATCH v2 2/7 Add macros for recording init calls during UBoot execution

From: Andrew Murray <[email protected]>

This patch adds macros which allow for the instrumentation of UBoot boot time. The macros can be used to call existing initialisation functions during start up. Each macro adds printf statements before and after the initialisation call.
---
Changes for v2:
- Use dedicated printf with timestamp function
- Allow DO_INITCALL_RET macro to provide return value

Signed-off-by Andrew Murray <[email protected]>
---
 include/common.h |   25 +++++++++++++++++++++++++
 1 files changed, 25 insertions(+), 0 deletions(-)
include/common.h +25 -0
index 1e21b7a..a926430 100644
@@ -176,6 +176,31 @@ typedef void (interrupt_handler_t)(void *);
 
 #endif /* CONFIG_SERIAL_MULTI */
 
+#if defined(CONFIG_BOOT_TRACE)
+#define DO_INITCALL(x, ...) \
+	do { \
+		printf_boot_trace("calling  0x%pF\n", x); \
+		(x)(__VA_ARGS__); \
+		printf_boot_trace("initcall 0x%pF returned\n", x); \
+	} while (0)
+#define DO_INITCALL_RET(x, ...) \
+	({ \
+		int __ret; \
+		printf_boot_trace("calling  0x%pF\n", x); \
+		__ret = (x)(__VA_ARGS__); \
+		printf_boot_trace("initcall 0x%pF returned\n", x); \
+		__ret; \
+	})
+#define DO_INITCALL_END(x) \
+	printf_boot_trace("initcall 0x%pF returned\n", x)
+#else
+#define DO_INITCALL(x, ...) \
+	(x)(__VA_ARGS__)
+#define DO_INITCALL_RET(x, ret, ...) \
+	ret = (x)(__VA_ARGS__)
+#define DO_INITCALL_END(x)
+#endif
+
 /*
  * General Purpose Utilities
  */
Signature · 1 line
1.7.4.1
author
#31 lore raw

PATCH v2 2/7 Add macros for recording init calls during UBoot execution

From: Andrew Murray <[email protected]>

The previous patch included a compile error when the CONFIG_BOOT_TRACE macro is not set, this is an update to that patch
---
This patch adds macros which allow for the instrumentation of UBoot boot time. The macros can be used to call existing initialisation functions during start up. Each macro adds printf statements before and after the initialisation call.
---
Changes for v2:
- Use dedicated printf with timestamp function
- Allow DO_INITCALL_RET macro to provide return value

Signed-off-by Andrew Murray <[email protected]>
---
 include/common.h |   29 +++++++++++++++++++++++++++++
 1 files changed, 29 insertions(+), 0 deletions(-)
include/common.h +29 -0
index 1e21b7a..196c306 100644
@@ -176,6 +176,33 @@ typedef void (interrupt_handler_t)(void *);
 
 #endif /* CONFIG_SERIAL_MULTI */
 
+#if defined(CONFIG_BOOT_TRACE)
+#define DO_INITCALL(x, ...) \
+	do { \
+		printf_boot_trace("calling  0x%pF\n", x); \
+		(x)(__VA_ARGS__); \
+		printf_boot_trace("initcall 0x%pF returned\n", x); \
+	} while (0)
+#define DO_INITCALL_RET(x, ...) \
+	({ \
+		int __ret; \
+		printf_boot_trace("calling  0x%pF\n", x); \
+		__ret = (x)(__VA_ARGS__); \
+		printf_boot_trace("initcall 0x%pF returned\n", x); \
+		__ret; \
+	})
+#define DO_INITCALL_END(x) \
+	do { \
+		printf_boot_trace("initcall 0x%pF returned\n", x); \
+	} while (0)
+#else
+#define DO_INITCALL(x, ...) \
+	({ (x)(__VA_ARGS__); })
+#define DO_INITCALL_RET(x, ...) \
+	({ (x)(__VA_ARGS__); })
+#define DO_INITCALL_END(x)
+#endif
+
 /*
  * General Purpose Utilities
  */

@@ -687,6 +714,8 @@ void	puts(const char *s);
 int	printf(const char *fmt, ...)
 		__attribute__ ((format (__printf__, 1, 2)));
 int	vprintf(const char *fmt, va_list args);
+int	printf_boot_trace(const char *fmt, ...)
+		__attribute__ ((format (__printf__, 1, 2)));
 
 /* stderr */
 #define eputc(c)		fputc(stderr, c)
Signature · 1 line
1.7.4.1
#32 lore raw

PATCH v2 2/7 Add macros for recording init calls during UBoot execution

include/common.h typedef void (interrupt_handler_t)(void *); · line 200

Quoted 3 lines · On Saturday, September 10, 2011 09:17:28 Andrew Murray wrote:
include/common.h +3 -0
+#else
+#define DO_INITCALL(x, ...) \
+	({ (x)(__VA_ARGS__); })

this should be do{}while(0) to avoid differences in behavior with the other DO_INITCALL() helper

include/common.h typedef void (interrupt_handler_t)(void *); · line 203

Quoted 6 lines
include/common.h +5 -0
+#define DO_INITCALL_END(x) \
+	do { \
+		printf_boot_trace("initcall 0x%pF returned\n", x); \
+	} while (0)
...
+#define DO_INITCALL_END(x)

seems like these should be merged so that dead code isnt caught in the middle

#ifdef CONFIG_BOOT_TRACE

# define _BOOT_TRACE 1
#else
# define _BOOT_TRACE 0
#endif
#define DO_INITCALL_END(x) \
	do { \
		if (_BOOT_TRACE) \
			printf_boot_trace("initcall 0x%pF returned\n", x); \
	} while (0)

although, if printf_boot_trace() itself had CONFIG_BOOT_TRACE logic in it, you wouldnt have to have DO_INITCALL_END() take care of wrapping things ... -mike
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 836 bytes
Desc: This is a digitally signed message part.
Url : http://lists.denx.de/pipermail/u-boot/attachments/20110917/e18904fc/attachment.pgp

author
#33 lore raw

PATCH v2 3/7 Add timing information to printf's for use with bootgraph.pl

In reply to Andrew Murray

From: Andrew Murray <[email protected]>

This patch adds timings information to printfs.
---
Changes for v2:
- Add dedicated function to printf with timestamps
- Fix compiler warnings
- Remove code duplication within printf

Signed-off-by Andrew Murray <[email protected]>
---
 common/console.c |   27 ++++++++++++++++++++++++---
 include/common.h |    2 ++
 2 files changed, 26 insertions(+), 3 deletions(-)
common/console.c +24 -3
index 8c650e0..63b84ba 100644
@@ -365,24 +365,45 @@ void puts(const char *s)
 	}
 }
 
-int printf(const char *fmt, ...)
+#if defined(CONFIG_BOOT_TRACE)
+int printf_boot_trace(const char *fmt, ...)
 {
 	va_list args;
-	uint i;
+	uint i = 0;
 	char printbuffer[CONFIG_SYS_PBSIZE];
+	char *buf = printbuffer;
 
+	unsigned long long ticks = get_ticks();
+	uint secs = ticks / get_tbclk();
+	uint msec = ((ticks * 1000000) / get_tbclk()) - (secs * 1000000);
+
+	i += sprintf(buf, "[%5u.%06u] ", secs, msec);
+	buf += i;
 	va_start(args, fmt);
 
 	/* For this to work, printbuffer must be larger than
 	 * anything we ever want to print.
 	 */
-	i = vsprintf(printbuffer, fmt, args);
+	i += vsprintf(buf, fmt, args);
 	va_end(args);
 
 	/* Print the string */
 	puts(printbuffer);
 	return i;
 }
+#endif
+
+int printf(const char *fmt, ...)
+{
+	va_list args;
+	uint i = 0;
+
+	va_start(args, fmt);
+	i = vprintf(fmt, args);
+	va_end(args);
+
+	return i;
+}
 
 int vprintf(const char *fmt, va_list args)
 {
include/common.h +2 -0
index a926430..16175b4 100644
@@ -712,6 +712,8 @@ void	puts(const char *s);
 int	printf(const char *fmt, ...)
 		__attribute__ ((format (__printf__, 1, 2)));
 int	vprintf(const char *fmt, va_list args);
+int	printf_boot_trace(const char *fmt, ...)
+		__attribute__ ((format (__printf__, 1, 2)));
 
 /* stderr */
 #define eputc(c)		fputc(stderr, c)
Signature · 1 line
1.7.4.1
#34 lore raw

PATCH v2 3/7 Add timing information to printf's for use with bootgraph.pl

common/console.c void puts(const char *s) · line 406

Quoted 11 lines · On Saturday, September 10, 2011 08:37:03 Andrew Murray wrote:
common/console.c +11 -0
+int printf(const char *fmt, ...)
+{
+	va_list args;
+	uint i = 0;
+
+	va_start(args, fmt);
+	i = vprintf(fmt, args);
+	va_end(args);
+
+	return i;
+}

could you split this change out by itself ? this reduces code duplication between the printf/vprintf funcs.
-mike
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 836 bytes
Desc: This is a digitally signed message part.
Url : http://lists.denx.de/pipermail/u-boot/attachments/20110917/7867500e/attachment.pgp

author
#35 lore raw

PATCH v2 4/7 Add bootgraph instrumentation for ARM boards

In reply to Andrew Murray

From: Andrew Murray <[email protected]>

This patch adds bootgraph instrumentation for ARM boards.
---
Changes for v2:
- Use improvde DO_INITCALL_RET macro
- Fix compiler warnings

Signed-off-by Andrew Murray <[email protected]>
---
 arch/arm/lib/board.c |   26 +++++++++++++++++---------
 1 files changed, 17 insertions(+), 9 deletions(-)
arch/arm/lib/board.c +17 -9
index 169dfeb..7b09bf1 100644
@@ -282,7 +282,7 @@ void board_init_f (ulong bootflag)
 	gd->mon_len = _bss_end_ofs;
 
 	for (init_fnc_ptr = init_sequence; *init_fnc_ptr; ++init_fnc_ptr) {
-		if ((*init_fnc_ptr)() != 0) {
+		if (DO_INITCALL_RET(*init_fnc_ptr) != 0) {
 			hang ();
 		}
 	}

@@ -416,6 +416,9 @@ void board_init_f (ulong bootflag)
 	debug ("relocation Offset is: %08lx\n", gd->reloc_off);
 	memcpy (id, (void *)gd, sizeof (gd_t));
 
+#if defined(CONFIG_BOOT_TRACE)
+	printf("performing relocate to ram to 0x%08lx\n", addr);
+#endif
 	relocate_code (addr_sp, id, addr);
 
 	/* NOTREACHED - relocate_code() does not return */

@@ -444,6 +447,10 @@ void board_init_r (gd_t *id, ulong dest_addr)
 	ulong flash_size;
 #endif
 
+#if defined(CONFIG_BOOT_TRACE)
+	printf("completed relocate to ram\n");
+#endif
+
 	gd = id;
 	bd = gd->bd;
 

@@ -451,7 +458,8 @@ void board_init_r (gd_t *id, ulong dest_addr)
 
 	monitor_flash_len = _end_ofs;
 	debug ("monitor flash len: %08lX\n", monitor_flash_len);
-	board_init();	/* Setup chipselects */
+
+	DO_INITCALL(board_init);	/* Setup chipselects */
 
 #ifdef CONFIG_SERIAL_MULTI
 	serial_initialize();

@@ -499,7 +507,7 @@ void board_init_r (gd_t *id, ulong dest_addr)
 
 #if defined(CONFIG_CMD_NAND)
 	puts ("NAND:  ");
-	nand_init();		/* go init the NAND */
+	DO_INITCALL(nand_init);		/* go init the NAND */
 #endif
 
 #if defined(CONFIG_CMD_ONENAND)

@@ -508,7 +516,7 @@ void board_init_r (gd_t *id, ulong dest_addr)
 
 #ifdef CONFIG_GENERIC_MMC
        puts("MMC:   ");
-       mmc_initialize(bd);
+       DO_INITCALL(mmc_initialize, bd);
 #endif
 
 #ifdef CONFIG_HAS_DATAFLASH

@@ -517,7 +525,7 @@ void board_init_r (gd_t *id, ulong dest_addr)
 #endif
 
 	/* initialize environment */
-	env_relocate ();
+	DO_INITCALL(env_relocate);
 
 #if defined(CONFIG_CMD_PCI) || defined(CONFIG_PCI)
 	arm_pci_init();

@@ -526,16 +534,16 @@ void board_init_r (gd_t *id, ulong dest_addr)
 	/* IP Address */
 	gd->bd->bi_ip_addr = getenv_IPaddr ("ipaddr");
 
-	stdio_init ();	/* get the devices list going. */
+	DO_INITCALL(stdio_init);	/* get the devices list going. */
 
-	jumptable_init ();
+	DO_INITCALL(jumptable_init);
 
 #if defined(CONFIG_API)
 	/* Initialize API */
 	api_init ();
 #endif
 
-	console_init_r ();	/* fully init console as a device */
+	DO_INITCALL(console_init_r);	/* fully init console as a device */
 
 #if defined(CONFIG_ARCH_MISC_INIT)
 	/* miscellaneous arch dependent initialisations */

@@ -543,7 +551,7 @@ void board_init_r (gd_t *id, ulong dest_addr)
 #endif
 #if defined(CONFIG_MISC_INIT_R)
 	/* miscellaneous platform dependent initialisations */
-	misc_init_r ();
+	DO_INITCALL(misc_init_r);
 #endif
 
 	 /* set up exceptions */
Signature · 1 line
1.7.4.1
#36 lore raw

PATCH v2 4/7 Add bootgraph instrumentation for ARM boards

arch/arm/lib/board.c void board_init_r (gd_t *id, ulong dest_addr) · line 452

Quoted 3 lines · On Saturday, September 10, 2011 08:37:04 Andrew Murray wrote:
arch/arm/lib/board.c +3 -0
+#if defined(CONFIG_BOOT_TRACE)
+	printf("completed relocate to ram\n");
+#endif

looks like you should have a boot trace printf helper to avoid having to put ifdef's around all of these printf call sites
-mike
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 836 bytes
Desc: This is a digitally signed message part.
Url : http://lists.denx.de/pipermail/u-boot/attachments/20110917/85687bf0/attachment.pgp

#37 lore raw

PATCH v2 4/7 Add bootgraph instrumentation for ARM boards

In reply to Andrew Murray

Dear Andrew Murray,

Quoted 8 lines · In message <[email protected]> you wrote:

From: Andrew Murray <[email protected]>

This patch adds bootgraph instrumentation for ARM boards.
---
Changes for v2:
- Use improvde DO_INITCALL_RET macro
- Fix compiler warnings

Quoted 4 lines
Signed-off-by Andrew Murray <[email protected]>
---
 arch/arm/lib/board.c |   26 +++++++++++++++++---------
 1 files changed, 17 insertions(+), 9 deletions(-)

Checkpatch says:

total: 0 errors, 2 warnings, 87 lines checked

Please clean up and resubmit. Thanks.

Best regards,

Wolfgang Denk

Signature · 4 lines
DENX Software Engineering GmbH,     MD: Wolfgang Denk & Detlev Zundel
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany
Phone: (+49)-8142-66989-10 Fax: (+49)-8142-66989-80 Email: wd at denx.de
"Engineering without management is art."               - Jeff Johnson
author
#38 lore raw

PATCH v2 5/7 Add bootgraph instrumentation for bootm command

In reply to Andrew Murray

Under normal operation the bootm command will never return - this patch adds additional instrumentation to signal the 'end' of the bootm command such that this point can be reflected in any bootgraph SVG.

Signed-off-by Andrew Murray <[email protected]>
---
 common/cmd_bootm.c |    1 +
 1 files changed, 1 insertions(+), 0 deletions(-)
common/cmd_bootm.c +1 -0
index 1966da4..147e8de 100644
@@ -697,6 +697,7 @@ int do_bootm (cmd_tbl_t *cmdtp, int flag, int argc, char * const argv[])
 
 	arch_preboot_os();
 
+	DO_INITCALL_END(do_bootm);
 	boot_fn(0, argc, argv, &images);
 
 	show_boot_progress (-9);
Signature · 1 line
1.7.4.1
author
#39 lore raw

PATCH v2 6/7 Add bootgraph instrumentation for UBoot commands

In reply to Andrew Murray

From: Andrew Murray <[email protected]>

This patch adds bootgraph instrumentation for all U_BOOT_CMDs where the HUSH parser is not used. The patch also adds instrumentation for the common boot delay.
---
Changes for v2:
- Use improved DO_INITCALL_RET macro

Signed-off-by Andrew Murray <[email protected]>
---
 common/main.c |    8 ++++----
 1 files changed, 4 insertions(+), 4 deletions(-)
common/main.c +4 -4
index 2730c6f..bf95463 100644
@@ -376,7 +376,7 @@ void main_loop (void)
 
 	debug ("### main_loop: bootcmd=\"%s\"\n", s ? s : "<UNDEFINED>");
 
-	if (bootdelay >= 0 && s && !abortboot (bootdelay)) {
+	if (bootdelay >= 0 && s && !DO_INITCALL_RET(abortboot, bootdelay)) {
 # ifdef CONFIG_AUTOBOOT_KEYED
 		int prev = disable_ctrlc(1);	/* disable Control C checking */
 # endif

@@ -385,11 +385,11 @@ void main_loop (void)
 		run_command (s, 0);
 # else
 		parse_string_outer(s, FLAG_PARSE_SEMICOLON |
-				    FLAG_EXIT_FROM_LOOP);
+			    FLAG_EXIT_FROM_LOOP);
 # endif
 
 # ifdef CONFIG_AUTOBOOT_KEYED
-		disable_ctrlc(prev);	/* restore Control C checking */
+			disable_ctrlc(prev);	/* restore Control C checking */
 # endif
 	}
 

@@ -1371,7 +1371,7 @@ int run_command (const char *cmd, int flag)
 #endif
 
 		/* OK - call function to do the command */
-		if ((cmdtp->cmd) (cmdtp, flag, argc, argv) != 0) {
+		if (DO_INITCALL_RET(cmdtp->cmd, cmdtp, flag, argc, argv) != 0) {
 			rc = -1;
 		}
Signature · 1 line
1.7.4.1
#40 lore raw

PATCH v2 6/7 Add bootgraph instrumentation for UBoot commands

Quoted 7 lines · On Saturday, September 10, 2011 08:37:06 Andrew Murray wrote:
common/main.c +0 -0
@@ -385,11 +385,11 @@ void main_loop (void)
 		run_command (s, 0);
 # else
 		parse_string_outer(s, FLAG_PARSE_SEMICOLON |

common/main.c void main_loop (void) · line 395

Quoted 10 lines
common/main.c +2 -2
-				    FLAG_EXIT_FROM_LOOP);
+			    FLAG_EXIT_FROM_LOOP);
 # endif
 
 # ifdef CONFIG_AUTOBOOT_KEYED
-		disable_ctrlc(prev);	/* restore Control C checking */
+			disable_ctrlc(prev);	/* restore Control C checking */
 # endif
 	}

i dont see any functional changes here, so just drop these hunks
-mike
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 836 bytes
Desc: This is a digitally signed message part.
Url : http://lists.denx.de/pipermail/u-boot/attachments/20110917/6e07c433/attachment.pgp

#41 lore raw

PATCH v2 6/7 Add bootgraph instrumentation for UBoot commands

In reply to Andrew Murray

Dear Andrew Murray,

Quoted 9 lines · In message <[email protected]> you wrote:

From: Andrew Murray <[email protected]>

This patch adds bootgraph instrumentation for all U_BOOT_CMDs where the HUSH parser is not used. The patch also adds instrumentation for the common boot delay.
---
Changes for v2:
- Use improved DO_INITCALL_RET macro

Quoted 4 lines
Signed-off-by Andrew Murray <[email protected]>
---
 common/main.c |    8 ++++----
 1 files changed, 4 insertions(+), 4 deletions(-)

Checkpatch says:

total: 0 errors, 1 warnings, 29 lines checked

Please clean up and resubmit. Thanks.

Best regards,

Wolfgang Denk

Signature · 4 lines
DENX Software Engineering GmbH,     MD: Wolfgang Denk & Detlev Zundel
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany
Phone: (+49)-8142-66989-10 Fax: (+49)-8142-66989-80 Email: wd at denx.de
God may be subtle, but He isn't plain mean.         - Albert Einstein
author
#42 lore raw

PATCH v2 7/7 Add documentation for bootgraph.pl

In reply to Andrew Murray

From: Andrew Murray <[email protected]>

Documentation for the CONFIG_BOOT_TRACE option.
---
Changes for v2:
- Update documentation for v2 changes

Signed-off-by Andrew Murray <[email protected]>
---
 doc/README.bootgraph |   54 ++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 54 insertions(+), 0 deletions(-)
 create mode 100644 doc/README.bootgraph
doc/README.bootgraph new file +54 -0
new file mode 100644
index 0000000..cdd8211
@@ -0,0 +1,54 @@
+Bootgraph Instrumentation
+-------------------------
+
+The CONFIG_BOOT_TRACE configuration option can be defined to output extensive
+instrumentation to assist in boot time reduction. The tools/bootgraph.pl script
+can utilise this instrumentation to generate an SVG graph showing where UBoot
+spends its time.
+
+When enabled all printf_boot_trace output is prefixed with timing information
+similar to the Linux kernel's CONFIG_PRINTK_TIME option. This allows you to
+measure the interval between operations which is useful for identifying long
+delays during UBoot operation.
+
+When enabled additional console output will be generated - this output includes
+the addresses of executed commands and instrumented functions. For example:
+
+[    2.456000] initcall 0x9ff86814 returned
+[    2.460000] calling  0x9ff7c338
+[    2.590000] initcall 0x9ff7c338 returned
+[    2.594000] calling  0x9ff864ac
+
+At present executed commands are only displayed when the HUSH parser
+(CONFIG_SYS_HUSH_PARSER) is not being used.
+
+Functions such as initialisation code can be instrumented by using the
+DO_INITCALLXXX macros found in include/common.h (see arch/arm/lib/board.c) for
+examples). For example:
+
+@@ -508,7 +518,7 @@ void board_init_r (gd_t *id, ulong dest_addr)
+
+ #ifdef CONFIG_GENERIC_MMC
+        puts("MMC:   ");
+-       mmc_initialize(bd);
++       DO_INITCALL(mmc_initialize, bd);
+ #endif
+
+For functions that do not return such as do_bootm function, the DO_INITCALL_END
+macro can be used to mark the latest point of the function.
+
+When CONFIG_BOOT_TIME is not defined the DO_INITCALLXXX macros continue to call
+the intended function and should not add overhead.
+
+An SVG graph can be generated which allows for the visualisation of UBoot boot
+time by using the tools/bootgraph.pl script. This script has been ported from
+the Linux kernel (scripts/bootgraph.pl) and is used in a similar way. For
+example:
+
+cat console_output | perl ./tools/bootgraph.pl > graph.svg
+
+Assuming console_output is a file containing the console output of UBoot with
+CONFIG_BOOT_TRACE enabled - the graph.svg file should provide a graphical
+representation of boot time with resolved function addresses.
+
+Andrew Murray <[email protected]>
Signature · 1 line
1.7.4.1
#43 lore raw

PATCH v2 1/7 Add bootgraph.pl script for generating a boot graph SVG file

In reply to Andrew Murray

Dear Andrew Murray,

Quoted 7 lines · In message <[email protected]> you wrote:

From: Andrew Murray <[email protected]>

This is a port of the kernel's script/bootgraph.pl script which generates an SVG image illustrating boot time in UBoot. The script relies on additional output generated by UBoot during boot when the CONFIG_BOOT_TRACE option is enabled.

Quoted 5 lines
Signed-off-by Andrew Murray <[email protected]>
---
 tools/bootgraph.pl |  189 ++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 189 insertions(+), 0 deletions(-)
 create mode 100755 tools/bootgraph.pl

Checkpatch says:

total: 4 errors, 28 warnings, 189 lines checked

Please clean up and resubmit. Thanks.

Best regards,

Wolfgang Denk

Signature · 5 lines
DENX Software Engineering GmbH,     MD: Wolfgang Denk & Detlev Zundel
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany
Phone: (+49)-8142-66989-10 Fax: (+49)-8142-66989-80 Email: wd at denx.de
Honest error is to be pitied, not ridiculed.
                                       -- Philip Earl of Chesterfield