[U-Boot] [PATCH 0/7] Bootgraph.pl instrumentation support for UBoot

[U-Boot] [PATCH 0/7] Bootgraph.pl instrumentation support for UBoot

[Andrew Murray]

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

-- 
1.7.4.1

[U-Boot] [PATCH 1/7] Add bootgraph.pl script for generating a boot graph SVG file

[Andrew Murray]

From: Andrew Murray <amurray@mpcdata.com>

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 <amurray@theiet.org>
---
 tools/bootgraph.pl |  189 ++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 189 insertions(+), 0 deletions(-)
 create mode 100755 tools/bootgraph.pl

diff --git a/tools/bootgraph.pl b/tools/bootgraph.pl
new file mode 100755
index 0000000..8b206b5
--- /dev/null
+++ b/tools/bootgraph.pl
@@ -0,0 +1,189 @@
+#!/usr/bin/perl
+
+# Copyright (C) 2011, Andrew Murray <amurray@theiet.org>)
+# Copyright (C) 2008, Intel Corporation (Arjan van de Ven <arjan@linux.intel.com>)
+#
+# 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";
-- 
1.7.4.1

[U-Boot] [PATCH 2/7] Add macros for recording init calls during UBoot execution

[Andrew Murray]

From: Andrew Murray <amurray@mpcdata.com>

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 <amurray@theiet.org>
---
 include/common.h |   23 +++++++++++++++++++++++
 1 files changed, 23 insertions(+), 0 deletions(-)

diff --git a/include/common.h b/include/common.h
index 1e21b7a..aa21b10 100644
--- a/include/common.h
+++ b/include/common.h
@@ -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
  */
-- 
1.7.4.1

[U-Boot] [PATCH 2/7] Add macros for recording init calls during UBoot execution

[Mike Frysinger]

On Wednesday, August 31, 2011 18:20:56 Andrew Murray wrote:
> +#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().

> +#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 

[U-Boot] [PATCH 2/7] Add macros for recording init calls during UBoot execution

[Andrew Murray]

On 31 August 2011 23:50, Mike Frysinger <vapier@gentoo.org> wrote:
> On Wednesday, August 31, 2011 18:20:56 Andrew Murray wrote:
>> +#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

[U-Boot] [PATCH 3/7] Add timing information to printf's for use with bootgraph.pl

[Andrew Murray]

From: Andrew Murray <amurray@mpcdata.com>

This patch adds timings information to printfs.

Signed-off-by: Andrew Murray <amurray@theiet.org>
---
 common/console.c |   12 +++++++++++-
 1 files changed, 11 insertions(+), 1 deletions(-)

diff --git a/common/console.c b/common/console.c
index 8c650e0..33de3fa 100644
--- a/common/console.c
+++ b/common/console.c
@@ -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 */
-- 
1.7.4.1

[U-Boot] [PATCH 3/7] Add timing information to printf's for use with bootgraph.pl

[Mike Frysinger]

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);
> 
> +#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);

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 

[U-Boot] [PATCH 3/7] Add timing information to printf's for use with bootgraph.pl

[Andrew Murray]

On 31 August 2011 23:47, Mike Frysinger <vapier@gentoo.org> wrote:
> 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);
>>
>> +#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);
>
> 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

[U-Boot] [PATCH 3/7] Add timing information to printf's for use with bootgraph.pl

[Graeme Russ]

Hi Mike, Andrew,

On Thu, Sep 1, 2011 at 8:47 AM, Mike Frysinger <vapier@gentoo.org> wrote:
> 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);
>>
>> +#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);
>
> 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

[U-Boot] [PATCH 3/7] Add timing information to printf's for use with bootgraph.pl

[Andrew Murray]

On 1 September 2011 00:38, Graeme Russ <graeme.russ@gmail.com> wrote:
> Hi Mike, Andrew,
>
> On Thu, Sep 1, 2011 at 8:47 AM, Mike Frysinger <vapier@gentoo.org> wrote:
>> 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);
>>>
>>> +#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);
>>
>> 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

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

[U-Boot] [PATCH 3/7] Add timing information to printf's for use with bootgraph.pl

[Wolfgang Denk]

Dear Mike Frysinger,

In message <201108311847.16042.vapier@gentoo.org> 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

-- 
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

[U-Boot] [PATCH 3/7] Add timing information to printf's for use with bootgraph.pl

[Mike Frysinger]

On Wednesday, September 07, 2011 17:10:03 Wolfgang Denk wrote:
> Mike Frysinger 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?

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 

[U-Boot] [PATCH 3/7] Add timing information to printf's for use with bootgraph.pl

[Wolfgang Denk]

Dear Mike Frysinger,

In message <201109082050.51313.vapier@gentoo.org> you wrote:
>
> > 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

-- 
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@denx.de
Die Scheu vor Verantwortung ist die Krankheit unserer Zeit.
                                                 -- Otto von Bismarck

[U-Boot] [PATCH 4/7] Add bootgraph instrumentation for ARM boards

[Andrew Murray]

From: Andrew Murray <amurray@mpcdata.com>

This patch adds bootgraph instrumentation for ARM boards.

Signed-off-by: Andrew Murray <amurray@theiet.org>
---
 arch/arm/lib/board.c |   28 +++++++++++++++++++---------
 1 files changed, 19 insertions(+), 9 deletions(-)

diff --git a/arch/arm/lib/board.c b/arch/arm/lib/board.c
index 169dfeb..e6bb8e2 100644
--- a/arch/arm/lib/board.c
+++ b/arch/arm/lib/board.c
@@ -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 */
-- 
1.7.4.1

[U-Boot] [PATCH 5/7] Add bootgraph instrumentation for bootm command

[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 <amurray@theiet.org>
---
 common/cmd_bootm.c |    1 +
 1 files changed, 1 insertions(+), 0 deletions(-)

diff --git a/common/cmd_bootm.c b/common/cmd_bootm.c
index 1966da4..147e8de 100644
--- a/common/cmd_bootm.c
+++ b/common/cmd_bootm.c
@@ -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);
-- 
1.7.4.1

[U-Boot] [PATCH 6/7] Add bootgraph instrumentation for UBoot commands

[Andrew Murray]

From: Andrew Murray <amurray@mpcdata.com>

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 <amurray@theiet.org>
---
 common/main.c |   19 ++++++++++++-------
 1 files changed, 12 insertions(+), 7 deletions(-)

diff --git a/common/main.c b/common/main.c
index 2730c6f..0c78a94 100644
--- a/common/main.c
+++ b/common/main.c
@@ -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;
 		}
 
-- 
1.7.4.1

[U-Boot] [PATCH 7/7] Add documentation for bootgraph.pl

[Andrew Murray]

From: Andrew Murray <amurray@mpcdata.com>

Documentation for the CONFIG_BOOT_TRACE option.

Signed-off-by: Andrew Murray <amurray@theiet.org>
---
 doc/README.bootgraph |   57 ++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 57 insertions(+), 0 deletions(-)
 create mode 100644 doc/README.bootgraph

diff --git a/doc/README.bootgraph b/doc/README.bootgraph
new file mode 100644
index 0000000..af8d9e4
--- /dev/null
+++ b/doc/README.bootgraph
@@ -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 <amurray@theiet.org>
-- 
1.7.4.1

[U-Boot] [PATCH 0/7] Bootgraph.pl instrumentation support for UBoot

[Mike Frysinger]

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.
> 
> 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 

[U-Boot] [PATCH 0/7] Bootgraph.pl instrumentation support for UBoot

[Simon Glass]

Hi Mike,

On Wed, Aug 31, 2011 at 3:47 PM, Mike Frysinger <vapier@gentoo.org> wrote:
> 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.
>>
>> 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
>

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

[U-Boot] [PATCH 0/7] Bootgraph.pl instrumentation support for UBoot

[Andrew Murray]

On 1 September 2011 00:12, Simon Glass <sjg@chromium.org> wrote:
> Hi Mike,
>
> On Wed, Aug 31, 2011 at 3:47 PM, Mike Frysinger <vapier@gentoo.org> wrote:
>> 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.
>>>
>>> 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
>>
>
> 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
>

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

[U-Boot] [PATCH 0/7] Bootgraph.pl instrumentation support for UBoot

[Graeme Russ]

Hi Andrew,

On Thu, Sep 1, 2011 at 9:25 AM, Andrew Murray <amurray@mpc-data.co.uk> wrote:
> On 1 September 2011 00:12, Simon Glass <sjg@chromium.org> wrote:
>> Hi Mike,
>>
>> On Wed, Aug 31, 2011 at 3:47 PM, Mike Frysinger <vapier@gentoo.org> wrote:
>>> 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]

>>>>
>>>> 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 :)

>>> -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
>>
>
> 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

[U-Boot] [PATCH 0/7] Bootgraph.pl instrumentation support for UBoot

[Simon Glass]

Hi Andrew,

On Wed, Aug 31, 2011 at 4:32 PM, Graeme Russ <graeme.russ@gmail.com> wrote:
> Hi Andrew,
>
> On Thu, Sep 1, 2011 at 9:25 AM, Andrew Murray <amurray@mpc-data.co.uk> wrote:
>> On 1 September 2011 00:12, Simon Glass <sjg@chromium.org> wrote:
>>> Hi Mike,
>>>
>>> On Wed, Aug 31, 2011 at 3:47 PM, Mike Frysinger <vapier@gentoo.org> wrote:
>>>> 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]
>
>>>>>
>>>>> 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 :)
>
>>>> -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
>>>
>>
>> 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.

>
> 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.

> 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

[U-Boot] [PATCH 0/7] Bootgraph.pl instrumentation support for UBoot

[Andrew Murray]

On 1 September 2011 00:39, Simon Glass <sjg@chromium.org> wrote:
>>>
>>> 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]

>
> 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

[U-Boot] [PATCH 0/7] Bootgraph.pl instrumentation support for UBoot

[Andrew Murray]

On 1 September 2011 00:53, Andrew Murray <amurray@theiet.org> wrote:

> >
> > 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

[U-Boot] [PATCH 0/7] Bootgraph.pl instrumentation support for UBoot

[Simon Glass]

Hi Andrew,

On Sat, Sep 10, 2011 at 5:40 AM, Andrew Murray <amurray@theiet.org> wrote:
> On 1 September 2011 00:53, Andrew Murray <amurray@theiet.org> wrote:
>>
>> >
>> > 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

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

[U-Boot] [PATCH 0/7] Bootgraph.pl instrumentation support for UBoot

[Graeme Russ]

Hi Simon,

On Tue, Sep 13, 2011 at 2:34 PM, Simon Glass <sjg@chromium.org> wrote:
> Hi Andrew,
>
> On Sat, Sep 10, 2011 at 5:40 AM, Andrew Murray <amurray@theiet.org> wrote:
>> On 1 September 2011 00:53, Andrew Murray <amurray@theiet.org> wrote:
>>>

>
> 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

[U-Boot] [PATCH 0/7] Bootgraph.pl instrumentation support for UBoot

[Simon Glass]

Hi Graeme,

On Mon, Sep 12, 2011 at 10:24 PM, Graeme Russ <graeme.russ@gmail.com> wrote:
> Hi Simon,
>
> On Tue, Sep 13, 2011 at 2:34 PM, Simon Glass <sjg@chromium.org> wrote:
>> Hi Andrew,
>>
>> On Sat, Sep 10, 2011 at 5:40 AM, Andrew Murray <amurray@theiet.org> wrote:
>>> On 1 September 2011 00:53, Andrew Murray <amurray@theiet.org> wrote:
>>>>
>
>>
>> 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.

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?

>
> 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

>
> Regards,
>
> Graeme
>

[U-Boot] [PATCH 0/7] Bootgraph.pl instrumentation support for UBoot

[Graeme Russ]

Hi Simon,

On 13/09/11 21:52, Simon Glass wrote:
> Hi Graeme,
> 
> On Mon, Sep 12, 2011 at 10:24 PM, Graeme Russ <graeme.russ@gmail.com> wrote:
>> Hi Simon,
>>
>> On Tue, Sep 13, 2011 at 2:34 PM, Simon Glass <sjg@chromium.org> wrote:
>>> Hi Andrew,
>>>
>>> On Sat, Sep 10, 2011 at 5:40 AM, Andrew Murray <amurray@theiet.org> wrote:
>>>> On 1 September 2011 00:53, Andrew Murray <amurray@theiet.org> wrote:
>>>>>

[snip]

>>  - 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

[U-Boot] [PATCH 0/7] Bootgraph.pl instrumentation support for UBoot

[Simon Glass]

Hi Graeme,

On Tue, Sep 13, 2011 at 5:01 AM, Graeme Russ <graeme.russ@gmail.com> wrote:
> Hi Simon,
>
> On 13/09/11 21:52, Simon Glass wrote:
>> Hi Graeme,
>>
>> On Mon, Sep 12, 2011 at 10:24 PM, Graeme Russ <graeme.russ@gmail.com> wrote:
>>> Hi Simon,
>>>
>>> On Tue, Sep 13, 2011 at 2:34 PM, Simon Glass <sjg@chromium.org> wrote:
>>>> Hi Andrew,
>>>>
>>>> On Sat, Sep 10, 2011 at 5:40 AM, Andrew Murray <amurray@theiet.org> wrote:
>>>>> On 1 September 2011 00:53, Andrew Murray <amurray@theiet.org> wrote:
>>>>>>
>
> [snip]
>
>>> ?- 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)

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

>
> 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.

>
> 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

>
> 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

>
> Regards,
>
> Graeme
>

[U-Boot] [PATCH v2 1/7] Add bootgraph.pl script for generating a boot graph SVG file

[Andrew Murray]

From: Andrew Murray <amurray@mpcdata.com>

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 <amurray@theiet.org>
---
 tools/bootgraph.pl |  189 ++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 189 insertions(+), 0 deletions(-)
 create mode 100755 tools/bootgraph.pl

diff --git a/tools/bootgraph.pl b/tools/bootgraph.pl
new file mode 100755
index 0000000..8b206b5
--- /dev/null
+++ b/tools/bootgraph.pl
@@ -0,0 +1,189 @@
+#!/usr/bin/perl
+
+# Copyright (C) 2011, Andrew Murray <amurray@theiet.org>)
+# Copyright (C) 2008, Intel Corporation (Arjan van de Ven <arjan@linux.intel.com>)
+#
+# 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";
-- 
1.7.4.1

[U-Boot] [PATCH v2 2/7] Add macros for recording init calls during UBoot execution

[Andrew Murray]

From: Andrew Murray <amurray@mpcdata.com>

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 <amurray@theiet.org>
---
 include/common.h |   25 +++++++++++++++++++++++++
 1 files changed, 25 insertions(+), 0 deletions(-)

diff --git a/include/common.h b/include/common.h
index 1e21b7a..a926430 100644
--- a/include/common.h
+++ b/include/common.h
@@ -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
  */
-- 
1.7.4.1

[U-Boot] [PATCH v2 2/7] Add macros for recording init calls during UBoot execution

[Andrew Murray]

From: Andrew Murray <amurray@mpcdata.com>

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 <amurray@theiet.org>
---
 include/common.h |   29 +++++++++++++++++++++++++++++
 1 files changed, 29 insertions(+), 0 deletions(-)

diff --git a/include/common.h b/include/common.h
index 1e21b7a..196c306 100644
--- a/include/common.h
+++ b/include/common.h
@@ -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)
-- 
1.7.4.1

[U-Boot] [PATCH v2 2/7] Add macros for recording init calls during UBoot execution

[Mike Frysinger]

On Saturday, September 10, 2011 09:17:28 Andrew Murray wrote:
> +#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

> +#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 

[U-Boot] [PATCH v2 3/7] Add timing information to printf's for use with bootgraph.pl

[Andrew Murray]

From: Andrew Murray <amurray@mpcdata.com>

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 <amurray@theiet.org>
---
 common/console.c |   27 ++++++++++++++++++++++++---
 include/common.h |    2 ++
 2 files changed, 26 insertions(+), 3 deletions(-)

diff --git a/common/console.c b/common/console.c
index 8c650e0..63b84ba 100644
--- a/common/console.c
+++ b/common/console.c
@@ -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)
 {
diff --git a/include/common.h b/include/common.h
index a926430..16175b4 100644
--- a/include/common.h
+++ b/include/common.h
@@ -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)
-- 
1.7.4.1

[U-Boot] [PATCH v2 3/7] Add timing information to printf's for use with bootgraph.pl

[Mike Frysinger]

On Saturday, September 10, 2011 08:37:03 Andrew Murray wrote:
> +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 

[U-Boot] [PATCH v2 4/7] Add bootgraph instrumentation for ARM boards

[Andrew Murray]

From: Andrew Murray <amurray@mpcdata.com>

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 <amurray@theiet.org>
---
 arch/arm/lib/board.c |   26 +++++++++++++++++---------
 1 files changed, 17 insertions(+), 9 deletions(-)

diff --git a/arch/arm/lib/board.c b/arch/arm/lib/board.c
index 169dfeb..7b09bf1 100644
--- a/arch/arm/lib/board.c
+++ b/arch/arm/lib/board.c
@@ -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 */
-- 
1.7.4.1

[U-Boot] [PATCH v2 4/7] Add bootgraph instrumentation for ARM boards

[Mike Frysinger]

On Saturday, September 10, 2011 08:37:04 Andrew Murray wrote:
> +#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 

[U-Boot] [PATCH v2 4/7] Add bootgraph instrumentation for ARM boards

[Wolfgang Denk]

Dear Andrew Murray,

In message <1315658227-4388-4-git-send-email-amurray@theiet.org> you wrote:
> From: Andrew Murray <amurray@mpcdata.com>
> 
> 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 <amurray@theiet.org>
> ---
>  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

-- 
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

[U-Boot] [PATCH v2 5/7] Add bootgraph instrumentation for bootm command

[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 <amurray@theiet.org>
---
 common/cmd_bootm.c |    1 +
 1 files changed, 1 insertions(+), 0 deletions(-)

diff --git a/common/cmd_bootm.c b/common/cmd_bootm.c
index 1966da4..147e8de 100644
--- a/common/cmd_bootm.c
+++ b/common/cmd_bootm.c
@@ -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);
-- 
1.7.4.1

[U-Boot] [PATCH v2 6/7] Add bootgraph instrumentation for UBoot commands

[Andrew Murray]

From: Andrew Murray <amurray@mpcdata.com>

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 <amurray@theiet.org>
---
 common/main.c |    8 ++++----
 1 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/common/main.c b/common/main.c
index 2730c6f..bf95463 100644
--- a/common/main.c
+++ b/common/main.c
@@ -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;
 		}
 
-- 
1.7.4.1

[U-Boot] [PATCH v2 6/7] Add bootgraph instrumentation for UBoot commands

[Mike Frysinger]

On Saturday, September 10, 2011 08:37:06 Andrew Murray wrote:
> --- a/common/main.c
> +++ b/common/main.c
>
> @@ -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
>  	}
> 

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 

[U-Boot] [PATCH v2 6/7] Add bootgraph instrumentation for UBoot commands

[Wolfgang Denk]

Dear Andrew Murray,

In message <1315658227-4388-6-git-send-email-amurray@theiet.org> you wrote:
> From: Andrew Murray <amurray@mpcdata.com>
> 
> 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 <amurray@theiet.org>
> ---
>  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

-- 
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

[U-Boot] [PATCH v2 7/7] Add documentation for bootgraph.pl

[Andrew Murray]

From: Andrew Murray <amurray@mpcdata.com>

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

Signed-off-by: Andrew Murray <amurray@theiet.org>
---
 doc/README.bootgraph |   54 ++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 54 insertions(+), 0 deletions(-)
 create mode 100644 doc/README.bootgraph

diff --git a/doc/README.bootgraph b/doc/README.bootgraph
new file mode 100644
index 0000000..cdd8211
--- /dev/null
+++ b/doc/README.bootgraph
@@ -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 <amurray@theiet.org>
-- 
1.7.4.1

[U-Boot] [PATCH v2 1/7] Add bootgraph.pl script for generating a boot graph SVG file

[Wolfgang Denk]

Dear Andrew Murray,

In message <1315658227-4388-1-git-send-email-amurray@theiet.org> you wrote:
> From: Andrew Murray <amurray@mpcdata.com>
> 
> 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 <amurray@theiet.org>
> ---
>  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

-- 
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