[U-Boot] [PATCH 0/7] 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
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%5C%22%3E%5Cn"; + +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";
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 */
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
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
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 */
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
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
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
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
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
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
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
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 */
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);
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; }
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
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
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
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
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
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
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
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
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
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
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
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
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
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%5C%22%3E%5Cn"; + +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";
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 */
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)
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
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)
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
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 */
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
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
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);
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; }
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
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
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
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
participants (6)
-
Andrew Murray -
Andrew Murray -
Graeme Russ -
Mike Frysinger -
Simon Glass -
Wolfgang Denk