bootstage: Implement core microsecond boot time measurement
authorSimon Glass <sjg@chromium.org>
Mon, 13 Feb 2012 13:51:19 +0000 (13:51 +0000)
committerWolfgang Denk <wd@denx.de>
Sun, 18 Mar 2012 20:42:14 +0000 (21:42 +0100)
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
common/Makefile
common/bootstage.c [new file with mode: 0644]
include/bootstage.h

diff --git a/README b/README
index 89646725a0b884c5b8b10e4262a1682478788a29..1f8bd204955c0c920a0c390459ea50beb7984bcf 100644 (file)
--- a/README
+++ b/README
@@ -2261,6 +2261,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
index 2a31c6285b5e948156d63ab8efc1d3139c71b22d..fd9b3b053d72c6c05bd7b59bc9e988a00db8baed 100644 (file)
@@ -172,6 +172,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 (file)
index 0000000..d2bbe63
--- /dev/null
@@ -0,0 +1,158 @@
+/*
+ * 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 */
+       show_boot_progress(flags & BOOTSTAGEF_ERROR ? -id : id);
+       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[15], *s;
+       int grab = 3;
+
+       /* We don't seem to have %'d in U-Boot */
+       sprintf(str, "%12lu", us_time);
+       for (s = str + 3; *s; s += grab) {
+               if (s != str + 3)
+                       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 ? 1 : -1;
+}
+
+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);
+}
index b56d95351c8f8d850fd84dc4534e4752641a4ca1..06ab2c8ef0c8c358703cfd6a36f84001689dbf97 100644 (file)
 #ifndef _BOOTSTAGE_H
 #define _BOOTSTAGE_H
 
+/* 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
@@ -169,6 +174,33 @@ 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,
 };
 
 /*
@@ -189,6 +221,11 @@ 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(),
@@ -207,6 +244,12 @@ static inline ulong bootstage_error(enum bootstage_id id)
        return 0;
 }
 
+static inline ulong bootstage_mark_name(enum bootstage_id id, const char *name)
+{
+       return 0;
+}
+
+
 #endif /* CONFIG_BOOTSTAGE */
 
 #endif