[U-Boot] [RFC PATCH v2 13/15] bootstage: Add microsecond boot time measurement

Simon Glass
2011-12-10T21:08:05Z

This defines the basics of a new boot time measurement feature. This allows
logging of very accurate time measurements as the boot proceeds, by using
an available microsecond counter.

To enable the feature, define CONFIG_BOOTSTAGE in your board config file.
Also available is CONFIG_BOOTSTAGE_REPORT which will cause a report to be
printed just before handing off to the OS.

Most IDs are not named at this stage. For that I would first like to
renumber them all.

Timer summary in microseconds:
Mark Elapsed Stage
0 0 reset
205,000 205,000 board_init_f
6,053,000 5,848,000 bootm_start
6,053,000 0 id=1
6,058,000 5,000 id=101
6,058,000 0 id=100
6,061,000 3,000 id=103
6,064,000 3,000 id=104
6,093,000 29,000 id=107
6,093,000 0 id=106
6,093,000 0 id=105
6,093,000 0 id=108
7,089,000 996,000 id=7
7,089,000 0 id=15
7,089,000 0 id=8
7,097,000 8,000 start_kernel

Signed-off-by: Simon Glass <sjg@chromium.org>
---

README | 25 ++++++++
common/Makefile | 1 +
common/bootstage.c | 160 +++++++++++++++++++++++++++++++++++++++++++++++++++
include/bootstage.h | 75 +++++++++++++++++++++++-
4 files changed, 259 insertions(+), 2 deletions(-)
create mode 100644 common/bootstage.c

diff --git a/README b/README
index e9d1891..20c09e6 100644
--- a/README
+++ b/README
@@ -2198,6 +2198,31 @@ The following options need to be configured:
example, some LED's) on your board. At the moment,
the following checkpoints are implemented:

+- Detailed boot stage timing
+ CONFIG_BOOTSTAGE
+ Define this option to get detailed timing of each stage
+ of the boot process.
+
+ CONFIG_BOOTSTAGE_USER_COUNT
+ This is the number of available user bootstage records.
+ Each time you call bootstage_mark(BOOTSTAGE_ID_ALLOC, ...)
+ a new ID will be allocated from this stash. If you exceed
+ the limit, recording will stop.
+
+ CONFIG_BOOTSTAGE_REPORT
+ Define this to print a report before boot, similar to this:
+
+ Timer summary in microseconds:
+ Mark Elapsed Stage
+ 0 0 reset
+ 3,575,678 3,575,678 board_init_f start
+ 3,575,695 17 arch_cpu_init A9
+ 3,575,777 82 arch_cpu_init done
+ 3,659,598 83,821 board_init_r start
+ 3,910,375 250,777 main_loop
+ 29,916,167 26,005,792 bootm_start
+ 30,361,327 445,160 start_kernel
+
Legacy uImage format:

Arg Where When
diff --git a/common/Makefile b/common/Makefile
index 1be7236..5530f2c 100644
--- a/common/Makefile
+++ b/common/Makefile
@@ -175,6 +175,7 @@ SPD := y
endif
COBJS-$(SPD) += ddr_spd.o
COBJS-$(CONFIG_HWCONFIG) += hwconfig.o
+COBJS-$(CONFIG_BOOTSTAGE) += bootstage.o
COBJS-$(CONFIG_CONSOLE_MUX) += iomux.o
COBJS-y += flash.o
COBJS-$(CONFIG_CMD_KGDB) += kgdb.o kgdb_stubs.o
diff --git a/common/bootstage.c b/common/bootstage.c
new file mode 100644
index 0000000..358e1ca
--- /dev/null
+++ b/common/bootstage.c
@@ -0,0 +1,160 @@
+/*
+ * Copyright (c) 2011, Google Inc. All rights reserved.
+ *
+ * See file CREDITS for list of people who contributed to this
+ * project.
+ *
+ * This program 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; either version 2 of
+ * the License, or (at your option) any later version.
+ *
+ * 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; if not, write to the Free Software
+ * Foundation, Inc., 59 Temple Place, Suite 330, Boston,
+ * MA 02111-1307 USA
+ */
+
+
+/*
+ * This module records the progress of boot and arbitrary commands, and
+ * permits accurate timestamping of each.
+ *
+ * TBD: Pass timings to kernel in the FDT
+ */
+
+#include <common.h>
+#include <libfdt.h>
+
+DECLARE_GLOBAL_DATA_PTR;
+
+enum bootstage_flags {
+ BOOTSTAGEF_ERROR = 1 << 0, /* Error record */
+ BOOTSTAGEF_ALLOC = 1 << 1, /* Allocate an id */
+};
+
+struct bootstage_record {
+ ulong time_us;
+ const char *name;
+ int flags; /* see enum bootstage_flags */
+ enum bootstage_id id;
+};
+
+static struct bootstage_record record[BOOTSTAGE_ID_COUNT] = { {1} };
+static int next_id = BOOTSTAGE_ID_USER;
+
+ulong bootstage_add_record(enum bootstage_id id, const char *name,
+ int flags)
+{
+ struct bootstage_record *rec;
+ ulong mark = timer_get_boot_us();
+
+ if (flags & BOOTSTAGEF_ALLOC)
+ id = next_id++;
+
+ if (id < BOOTSTAGE_ID_COUNT) {
+ rec = &record[id];
+
+ /* Only record the first event for each */
+ if (!rec->time_us) {
+ rec->time_us = mark;
+ rec->name = name;
+ rec->flags = flags;
+ rec->id = id;
+ }
+ }
+
+ /* Tell the board about this progress */
+#ifdef CONFIG_SHOW_BOOT_PROGRESS
+ show_boot_progress(flags & BOOTSTAGE_ERROR ? -id : id);
+#endif
+ return mark;
+}
+
+
+ulong bootstage_mark(enum bootstage_id id)
+{
+ return bootstage_add_record(id, NULL, 0);
+}
+
+ulong bootstage_error(enum bootstage_id id)
+{
+ return bootstage_add_record(id, NULL, BOOTSTAGEF_ERROR);
+}
+
+ulong bootstage_mark_name(enum bootstage_id id, const char *name)
+{
+ int flags = 0;
+
+ if (id == BOOTSTAGE_ID_ALLOC)
+ flags = BOOTSTAGEF_ALLOC;
+ return bootstage_add_record(id, name, flags);
+}
+
+static void print_time(unsigned long us_time)
+{
+ char str[12], *s;
+ int grab = 3;
+
+ /* We don't seem to have %'d in U-Boot */
+ sprintf(str, "%9ld", us_time);
+ for (s = str; *s; s += grab) {
+ if (s != str)
+ putc(s[-1] != ' ' ? ',' : ' ');
+ printf("%.*s", grab, s);
+ grab = 3;
+ }
+}
+
+static uint32_t print_time_record(enum bootstage_id id,
+ struct bootstage_record *rec, uint32_t prev)
+{
+ print_time(rec->time_us);
+ print_time(rec->time_us - prev);
+ if (rec->name)
+ printf(" %s\n", rec->name);
+ else if (id >= BOOTSTAGE_ID_USER)
+ printf(" user_%d\n", id - BOOTSTAGE_ID_USER);
+ else
+ printf(" id=%d\n", id);
+ return rec->time_us;
+}
+
+static int h_compare_record(const void *r1, const void *r2)
+{
+ const struct bootstage_record *rec1 = r1, *rec2 = r2;
+
+ return rec1->time_us - rec2->time_us;
+}
+
+void bootstage_report(void)
+{
+ struct bootstage_record *rec = record;
+ int id;
+ uint32_t prev;
+
+ puts("Timer summary in microseconds:\n");
+ printf("%11s%11s %s\n", "Mark", "Elapsed", "Stage");
+
+ /* Fake the first record - we could get it from early boot */
+ rec->name = "reset";
+ rec->time_us = 0;
+ prev = print_time_record(BOOTSTAGE_ID_AWAKE, rec, 0);
+
+ /* Sort records by increasing time */
+ qsort(record, ARRAY_SIZE(record), sizeof(*rec), h_compare_record);
+
+ for (id = 0; id < BOOTSTAGE_ID_COUNT; id++, rec++) {
+ if (rec->time_us != 0)
+ prev = print_time_record(rec->id, rec, prev);
+ }
+ if (next_id > BOOTSTAGE_ID_COUNT)
+ printf("(Overflowed internal boot id table by %d entries\n"
+ "- please increase CONFIG_BOOTSTAGE_USER_COUNT\n",
+ next_id - BOOTSTAGE_ID_COUNT);
+}
diff --git a/include/bootstage.h b/include/bootstage.h
index 882af20..fee686a 100644
--- a/include/bootstage.h
+++ b/include/bootstage.h
@@ -28,6 +28,11 @@
* to the user and passing it to the OS for logging / further analysis.
*/

+/* The number of boot stage records available for the user */
+#ifndef CONFIG_BOOTSTAGE_USER_COUNT
+#define CONFIG_BOOTSTAGE_USER_COUNT 20
+#endif
+
/*
* A list of boot stages that we know about. Each of these indicates the
* state that we are at, and the action that we are about to perform. For
@@ -171,8 +176,56 @@ enum bootstage_id {

BOOTSTAGE_ID_NAND_FIT_READ = 150,
BOOTSTAGE_ID_NAND_FIT_READ_OK,
+
+ /*
+ * These boot stages are new, higher level, and not directly related
+ * to the old boot progress numbers. They are useful for recording
+ * rough boot timing information.
+ */
+ BOOTSTAGE_ID_AWAKE,
+ BOOTSTAGE_ID_START_UBOOT_F,
+ BOOTSTAGE_ID_START_UBOOT_R,
+ BOOTSTAGE_ID_USB_START,
+ BOOTSTAGE_ID_ETH_START,
+ BOOTSTAGE_ID_BOOTP_START,
+ BOOTSTAGE_ID_BOOTP_STOP,
+ BOOTSTAGE_ID_BOOTM_START,
+ BOOTSTAGE_ID_BOOTM_HANDOFF,
+ BOOTSTAGE_ID_MAIN_LOOP,
+ BOOTSTAGE_KERNELREAD_START,
+ BOOTSTAGE_KERNELREAD_STOP,
+
+ BOOTSTAGE_ID_CPU_AWAKE,
+ BOOTSTAGE_ID_MAIN_CPU_AWAKE,
+ BOOTSTAGE_ID_MAIN_CPU_READY,
+
+ /* a few spare for the user, from here */
+ BOOTSTAGE_ID_USER,
+ BOOTSTAGE_ID_COUNT = BOOTSTAGE_ID_USER + CONFIG_BOOTSTAGE_USER_COUNT,
+ BOOTSTAGE_ID_ALLOC,
};

+#ifdef CONFIG_BOOTSTAGE
+/* This is the full bootstage implementation */
+
+/*
+ * Mark a time stamp for the current boot stage.
+ */
+ulong bootstage_mark(enum bootstage_id id);
+
+ulong bootstage_error(enum bootstage_id id);
+
+ulong bootstage_mark_name(enum bootstage_id id, const char *name);
+
+/* Print a report about boot time */
+void bootstage_report(void);
+
+#else
+/*
+ * This is a dummy implementation which just calls show_boot_progress(),
+ * and won't even do that unless CONFIG_SHOW_BOOT_PROGRESS is defined
+ */
+
/*
* Board-specific platform code can implement show_boot_progress () if
* needed.
@@ -181,9 +234,27 @@ enum bootstage_id {
* has occurred.
*/
void show_boot_progress(int val);
-static inline void show_boot_error(int val)
+
+static inline ulong bootstage_mark(enum bootstage_id id)
{
- show_boot_progress(-val);
+#ifdef CONFIG_SHOW_BOOT_PROGRESS
+ show_boot_progress(id);
+#endif
+ return 0;
}

+static inline ulong bootstage_error(enum bootstage_id id)
+{
+#ifdef CONFIG_SHOW_BOOT_PROGRESS
+ show_boot_progress(-id);
+#endif
+ return 0;
+}
+
+static inline ulong bootstage_mark_name(enum bootstage_id id, const char *name)
+{ return 0; }
+
+
+#endif /* CONFIG_BOOTSTAGE */
+
#endif
--
1.7.3.1