bootstage: Implement core microsecond boot time measurement

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>

bootstage: Implement core microsecond boot time measurement
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>
Simon Glass · Wolfgang Denk
1 parent 770605e4f9
Showing 4 changed files with 227 additions and 0 deletions Side-by-side Diff
README
common/Makefile
common/bootstage.c
include/bootstage.h
@@ -2261,6 +2261,31 @@
 		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
@@ -172,6 +172,7 @@
 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
+/*
+ * 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);
+}
@@ -26,6 +26,11 @@
 #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 @@
  
 	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_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(),
@@ -206,6 +243,12 @@
 	show_boot_progress(-id);
 	return 0;
 }
+
+static inline ulong bootstage_mark_name(enum bootstage_id id, const char *name)
+{
+	return 0;
+}
+
  
 #endif /* CONFIG_BOOTSTAGE */
...	...	@@ -2261,6 +2261,31 @@
2261	2261	example, some LED's) on your board. At the moment,
2262	2262	the following checkpoints are implemented:
2263	2263
	2264	+- Detailed boot stage timing
	2265	+ CONFIG_BOOTSTAGE
	2266	+ Define this option to get detailed timing of each stage
	2267	+ of the boot process.
	2268	+
	2269	+ CONFIG_BOOTSTAGE_USER_COUNT
	2270	+ This is the number of available user bootstage records.
	2271	+ Each time you call bootstage_mark(BOOTSTAGE_ID_ALLOC, ...)
	2272	+ a new ID will be allocated from this stash. If you exceed
	2273	+ the limit, recording will stop.
	2274	+
	2275	+ CONFIG_BOOTSTAGE_REPORT
	2276	+ Define this to print a report before boot, similar to this:
	2277	+
	2278	+ Timer summary in microseconds:
	2279	+ Mark Elapsed Stage
	2280	+ 0 0 reset
	2281	+ 3,575,678 3,575,678 board_init_f start
	2282	+ 3,575,695 17 arch_cpu_init A9
	2283	+ 3,575,777 82 arch_cpu_init done
	2284	+ 3,659,598 83,821 board_init_r start
	2285	+ 3,910,375 250,777 main_loop
	2286	+ 29,916,167 26,005,792 bootm_start
	2287	+ 30,361,327 445,160 start_kernel
	2288	+
2264	2289	Legacy uImage format:
2265	2290
2266	2291	Arg Where When
...	...	@@ -172,6 +172,7 @@
172	172	endif
173	173	COBJS-$(SPD) += ddr_spd.o
174	174	COBJS-$(CONFIG_HWCONFIG) += hwconfig.o
	175	+COBJS-$(CONFIG_BOOTSTAGE) += bootstage.o
175	176	COBJS-$(CONFIG_CONSOLE_MUX) += iomux.o
176	177	COBJS-y += flash.o
177	178	COBJS-$(CONFIG_CMD_KGDB) += kgdb.o kgdb_stubs.o
	1	+/*
	2	+ * Copyright (c) 2011, Google Inc. All rights reserved.
	3	+ *
	4	+ * See file CREDITS for list of people who contributed to this
	5	+ * project.
	6	+ *
	7	+ * This program is free software; you can redistribute it and/or
	8	+ * modify it under the terms of the GNU General Public License as
	9	+ * published by the Free Software Foundation; either version 2 of
	10	+ * the License, or (at your option) any later version.
	11	+ *
	12	+ * This program is distributed in the hope that it will be useful,
	13	+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
	14	+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
	15	+ * GNU General Public License for more details.
	16	+ *
	17	+ * You should have received a copy of the GNU General Public License
	18	+ * along with this program; if not, write to the Free Software
	19	+ * Foundation, Inc., 59 Temple Place, Suite 330, Boston,
	20	+ * MA 02111-1307 USA
	21	+ */
	22	+
	23	+
	24	+/*
	25	+ * This module records the progress of boot and arbitrary commands, and
	26	+ * permits accurate timestamping of each.
	27	+ *
	28	+ * TBD: Pass timings to kernel in the FDT
	29	+ */
	30	+
	31	+#include <common.h>
	32	+#include <libfdt.h>
	33	+
	34	+DECLARE_GLOBAL_DATA_PTR;
	35	+
	36	+enum bootstage_flags {
	37	+ BOOTSTAGEF_ERROR = 1 << 0, /* Error record */
	38	+ BOOTSTAGEF_ALLOC = 1 << 1, /* Allocate an id */
	39	+};
	40	+
	41	+struct bootstage_record {
	42	+ ulong time_us;
	43	+ const char *name;
	44	+ int flags; /* see enum bootstage_flags */
	45	+ enum bootstage_id id;
	46	+};
	47	+
	48	+static struct bootstage_record record[BOOTSTAGE_ID_COUNT] = { {1} };
	49	+static int next_id = BOOTSTAGE_ID_USER;
	50	+
	51	+ulong bootstage_add_record(enum bootstage_id id, const char *name,
	52	+ int flags)
	53	+{
	54	+ struct bootstage_record *rec;
	55	+ ulong mark = timer_get_boot_us();
	56	+
	57	+ if (flags & BOOTSTAGEF_ALLOC)
	58	+ id = next_id++;
	59	+
	60	+ if (id < BOOTSTAGE_ID_COUNT) {
	61	+ rec = &record[id];
	62	+
	63	+ /* Only record the first event for each */
	64	+ if (!rec->time_us) {
	65	+ rec->time_us = mark;
	66	+ rec->name = name;
	67	+ rec->flags = flags;
	68	+ rec->id = id;
	69	+ }
	70	+ }
	71	+
	72	+ /* Tell the board about this progress */
	73	+ show_boot_progress(flags & BOOTSTAGEF_ERROR ? -id : id);
	74	+ return mark;
	75	+}
	76	+
	77	+
	78	+ulong bootstage_mark(enum bootstage_id id)
	79	+{
	80	+ return bootstage_add_record(id, NULL, 0);
	81	+}
	82	+
	83	+ulong bootstage_error(enum bootstage_id id)
	84	+{
	85	+ return bootstage_add_record(id, NULL, BOOTSTAGEF_ERROR);
	86	+}
	87	+
	88	+ulong bootstage_mark_name(enum bootstage_id id, const char *name)
	89	+{
	90	+ int flags = 0;
	91	+
	92	+ if (id == BOOTSTAGE_ID_ALLOC)
	93	+ flags = BOOTSTAGEF_ALLOC;
	94	+ return bootstage_add_record(id, name, flags);
	95	+}
	96	+
	97	+static void print_time(unsigned long us_time)
	98	+{
	99	+ char str[15], *s;
	100	+ int grab = 3;
	101	+
	102	+ /* We don't seem to have %'d in U-Boot */
	103	+ sprintf(str, "%12lu", us_time);
	104	+ for (s = str + 3; *s; s += grab) {
	105	+ if (s != str + 3)
	106	+ putc(s[-1] != ' ' ? ',' : ' ');
	107	+ printf("%.*s", grab, s);
	108	+ grab = 3;
	109	+ }
	110	+}
	111	+
	112	+static uint32_t print_time_record(enum bootstage_id id,
	113	+ struct bootstage_record *rec, uint32_t prev)
	114	+{
	115	+ print_time(rec->time_us);
	116	+ print_time(rec->time_us - prev);
	117	+ if (rec->name)
	118	+ printf(" %s\n", rec->name);
	119	+ else if (id >= BOOTSTAGE_ID_USER)
	120	+ printf(" user_%d\n", id - BOOTSTAGE_ID_USER);
	121	+ else
	122	+ printf(" id=%d\n", id);
	123	+ return rec->time_us;
	124	+}
	125	+
	126	+static int h_compare_record(const void r1, const void r2)
	127	+{
	128	+ const struct bootstage_record rec1 = r1, rec2 = r2;
	129	+
	130	+ return rec1->time_us > rec2->time_us ? 1 : -1;
	131	+}
	132	+
	133	+void bootstage_report(void)
	134	+{
	135	+ struct bootstage_record *rec = record;
	136	+ int id;
	137	+ uint32_t prev;
	138	+
	139	+ puts("Timer summary in microseconds:\n");
	140	+ printf("%11s%11s %s\n", "Mark", "Elapsed", "Stage");
	141	+
	142	+ /* Fake the first record - we could get it from early boot */
	143	+ rec->name = "reset";
	144	+ rec->time_us = 0;
	145	+ prev = print_time_record(BOOTSTAGE_ID_AWAKE, rec, 0);
	146	+
	147	+ /* Sort records by increasing time */
	148	+ qsort(record, ARRAY_SIZE(record), sizeof(*rec), h_compare_record);
	149	+
	150	+ for (id = 0; id < BOOTSTAGE_ID_COUNT; id++, rec++) {
	151	+ if (rec->time_us != 0)
	152	+ prev = print_time_record(rec->id, rec, prev);
	153	+ }
	154	+ if (next_id > BOOTSTAGE_ID_COUNT)
	155	+ printf("(Overflowed internal boot id table by %d entries\n"
	156	+ "- please increase CONFIG_BOOTSTAGE_USER_COUNT\n",
	157	+ next_id - BOOTSTAGE_ID_COUNT);
	158	+}
...	...	@@ -26,6 +26,11 @@
26	26	#ifndef _BOOTSTAGE_H
27	27	#define _BOOTSTAGE_H
28	28
	29	+/* The number of boot stage records available for the user */
	30	+#ifndef CONFIG_BOOTSTAGE_USER_COUNT
	31	+#define CONFIG_BOOTSTAGE_USER_COUNT 20
	32	+#endif
	33	+
29	34	/*
30	35	* A list of boot stages that we know about. Each of these indicates the
31	36	* state that we are at, and the action that we are about to perform. For
...	...	@@ -169,6 +174,33 @@
169	174
170	175	BOOTSTAGE_ID_NAND_FIT_READ = 150,
171	176	BOOTSTAGE_ID_NAND_FIT_READ_OK,
	177	+
	178	+ /*
	179	+ * These boot stages are new, higher level, and not directly related
	180	+ * to the old boot progress numbers. They are useful for recording
	181	+ * rough boot timing information.
	182	+ */
	183	+ BOOTSTAGE_ID_AWAKE,
	184	+ BOOTSTAGE_ID_START_UBOOT_F,
	185	+ BOOTSTAGE_ID_START_UBOOT_R,
	186	+ BOOTSTAGE_ID_USB_START,
	187	+ BOOTSTAGE_ID_ETH_START,
	188	+ BOOTSTAGE_ID_BOOTP_START,
	189	+ BOOTSTAGE_ID_BOOTP_STOP,
	190	+ BOOTSTAGE_ID_BOOTM_START,
	191	+ BOOTSTAGE_ID_BOOTM_HANDOFF,
	192	+ BOOTSTAGE_ID_MAIN_LOOP,
	193	+ BOOTSTAGE_KERNELREAD_START,
	194	+ BOOTSTAGE_KERNELREAD_STOP,
	195	+
	196	+ BOOTSTAGE_ID_CPU_AWAKE,
	197	+ BOOTSTAGE_ID_MAIN_CPU_AWAKE,
	198	+ BOOTSTAGE_ID_MAIN_CPU_READY,
	199	+
	200	+ /* a few spare for the user, from here */
	201	+ BOOTSTAGE_ID_USER,
	202	+ BOOTSTAGE_ID_COUNT = BOOTSTAGE_ID_USER + CONFIG_BOOTSTAGE_USER_COUNT,
	203	+ BOOTSTAGE_ID_ALLOC,
172	204	};
173	205
174	206	/*
...	...	@@ -189,6 +221,11 @@
189	221
190	222	ulong bootstage_error(enum bootstage_id id);
191	223
	224	+ulong bootstage_mark_name(enum bootstage_id id, const char *name);
	225	+
	226	+/* Print a report about boot time */
	227	+void bootstage_report(void);
	228	+
192	229	#else
193	230	/*
194	231	* This is a dummy implementation which just calls show_boot_progress(),
...	...	@@ -206,6 +243,12 @@
206	243	show_boot_progress(-id);
207	244	return 0;
208	245	}
	246	+
	247	+static inline ulong bootstage_mark_name(enum bootstage_id id, const char *name)
	248	+{
	249	+ return 0;
	250	+}
	251	+
209	252
210	253	#endif /* CONFIG_BOOTSTAGE */
211	254