Kyösti Mälkki has uploaded this change for review. ( https://review.coreboot.org/c/coreboot/+/36574 )
Change subject: [WIP] boot_state: Exclude printk() from reported times ......................................................................
[WIP] boot_state: Exclude printk() from reported times
Change-Id: Id3998bab553ff803a93257a3f2c7bfea44c31729 Signed-off-by: Kyösti Mälkki kyosti.malkki@gmail.com --- M src/console/printk.c M src/include/console/console.h M src/lib/hardwaremain.c 3 files changed, 33 insertions(+), 0 deletions(-)
git pull ssh://review.coreboot.org:29418/coreboot refs/changes/74/36574/1
diff --git a/src/console/printk.c b/src/console/printk.c index 15c599d..e398c37 100644 --- a/src/console/printk.c +++ b/src/console/printk.c @@ -21,6 +21,7 @@ #include <smp/node.h> #include <stddef.h> #include <trace.h> +#include <timer.h>
#if (!defined(__PRE_RAM__) && CONFIG(HAVE_ROMSTAGE_CONSOLE_SPINLOCK)) || !CONFIG(HAVE_ROMSTAGE_CONSOLE_SPINLOCK) DECLARE_SPIN_LOCK(console_lock) @@ -44,6 +45,7 @@ int do_vprintk(int msg_level, const char *fmt, va_list args) { int i, log_this; + struct mono_time mt_start, mt_stop;
if (CONFIG(SQUELCH_EARLY_SMP) && ENV_ROMSTAGE_OR_BEFORE && !boot_cpu()) return 0; @@ -61,6 +63,9 @@ spin_lock(&console_lock); #endif
+ if (CONFIG(HAVE_MONOTONIC_TIMER)) + timer_monotonic_get(&mt_start); + if (log_this == CONSOLE_LOG_FAST) { i = vtxprintf(wrap_putchar_cbmemc, fmt, args, NULL); } else { @@ -68,6 +73,12 @@ console_tx_flush(); }
+ if (CONFIG(HAVE_MONOTONIC_TIMER)) { + timer_monotonic_get(&mt_stop); + if (ENV_RAMSTAGE) + console_accumulate_time(&mt_start, &mt_stop); + } + #ifdef __PRE_RAM__ #if CONFIG(HAVE_ROMSTAGE_CONSOLE_SPINLOCK) spin_unlock(romstage_console_lock()); diff --git a/src/include/console/console.h b/src/include/console/console.h index 1c2a276..11e16c9 100644 --- a/src/include/console/console.h +++ b/src/include/console/console.h @@ -53,6 +53,10 @@ */ void die_notify(void);
+struct mono_time; +void console_accumulate_time(const struct mono_time *start, + const struct mono_time *stop); + #define __CONSOLE_ENABLE__ \ ((ENV_BOOTBLOCK && CONFIG(BOOTBLOCK_CONSOLE)) || \ (ENV_POSTCAR && CONFIG(POSTCAR_CONSOLE)) || \ diff --git a/src/lib/hardwaremain.c b/src/lib/hardwaremain.c index 51ff330..98a0c12 100644 --- a/src/lib/hardwaremain.c +++ b/src/lib/hardwaremain.c @@ -63,6 +63,7 @@ struct boot_state_times { int num_samples; struct mono_time samples[MAX_TIME_SAMPLES]; + long console_usecs[MAX_TIME_SAMPLES]; };
/* The prologue (BS_ON_ENTRY) and epilogue (BS_ON_EXIT) of a state can be @@ -237,15 +238,28 @@ }
#if CONFIG(HAVE_MONOTONIC_TIMER) + +static long *console_usecs; + static void bs_sample_time(struct boot_state *state) { struct mono_time *mt;
+ console_usecs = &state->times.console_usecs[state->times.num_samples]; + *console_usecs = 0; + mt = &state->times.samples[state->times.num_samples]; timer_monotonic_get(mt); state->times.num_samples++; }
+void console_accumulate_time(const struct mono_time *start, + const struct mono_time *stop) +{ + if (console_usecs) + *console_usecs += mono_time_diff_microseconds(start, stop); +} + static void bs_report_time(struct boot_state *state) { long entry_time; @@ -257,6 +271,10 @@ run_time = mono_time_diff_microseconds(&samples[1], &samples[2]); exit_time = mono_time_diff_microseconds(&samples[2], &samples[3]);
+ entry_time -= state->times.console_usecs[0]; + run_time -= state->times.console_usecs[1]; + exit_time -= state->times.console_usecs[2]; + /* Report with millisecond precision to reduce log diffs. */ entry_time = DIV_ROUND_CLOSEST(entry_time, USECS_PER_MSEC); run_time = DIV_ROUND_CLOSEST(run_time, USECS_PER_MSEC);
Kyösti Mälkki has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36574 )
Change subject: [WIP] boot_state: Exclude printk() from reported times ......................................................................
Patch Set 1:
Log before (-) and after (+) this commit. The large number of zeroes makes me wonder if choice of precision in ms is too coarse. Serial console with LOGLEVEL=7 for both runs.
BS: BS_PRE_DEVICE times (ms): entry 0 run 0 exit 0 BS: BS_DEV_INIT_CHIPS times (ms): entry 0 run 0 exit 0 -BS: BS_DEV_ENUMERATE times (ms): entry 0 run 169 exit 0 +BS: BS_DEV_ENUMERATE times (ms): entry 0 run 0 exit 0 -BS: BS_DEV_RESOURCES times (ms): entry 0 run 431 exit 0 +BS: BS_DEV_RESOURCES times (ms): entry 0 run 2 exit 0 -BS: BS_DEV_ENABLE times (ms): entry 0 run 83 exit 0 +BS: BS_DEV_ENABLE times (ms): entry 0 run 0 exit 0 -BS: BS_DEV_INIT times (ms): entry 0 run 1204 exit 0 +BS: BS_DEV_INIT times (ms): entry 0 run 692 exit 0 -BS: BS_POST_DEVICE times (ms): entry 0 run 3 exit 0 +BS: BS_POST_DEVICE times (ms): entry 0 run 0 exit 0 BS: BS_OS_RESUME_CHECK times (ms): entry 0 run 0 exit 0 -BS: BS_WRITE_TABLES times (ms): entry 0 run 156 exit 0 +BS: BS_WRITE_TABLES times (ms): entry 0 run 4 exit 0 -BS: BS_PAYLOAD_LOAD times (ms): entry 0 run 112 exit 0 +BS: BS_PAYLOAD_LOAD times (ms): entry 0 run 64 exit 0
Hello build bot (Jenkins),
I'd like you to reexamine a change. Please visit
https://review.coreboot.org/c/coreboot/+/36574
to look at the new patch set (#2).
Change subject: [WIP] console,boot_state: Exclude printk() from reported times ......................................................................
[WIP] console,boot_state: Exclude printk() from reported times
Change-Id: Id3998bab553ff803a93257a3f2c7bfea44c31729 Signed-off-by: Kyösti Mälkki kyosti.malkki@gmail.com --- M src/arch/x86/postcar_loader.c M src/console/printk.c M src/include/console/console.h M src/lib/hardwaremain.c M src/lib/prog_loaders.c 5 files changed, 66 insertions(+), 0 deletions(-)
git pull ssh://review.coreboot.org:29418/coreboot refs/changes/74/36574/2
Hello build bot (Jenkins),
I'd like you to reexamine a change. Please visit
https://review.coreboot.org/c/coreboot/+/36574
to look at the new patch set (#3).
Change subject: [WIP] console,boot_state: Exclude printk() from reported times ......................................................................
[WIP] console,boot_state: Exclude printk() from reported times
Change-Id: Id3998bab553ff803a93257a3f2c7bfea44c31729 Signed-off-by: Kyösti Mälkki kyosti.malkki@gmail.com --- M src/arch/x86/postcar_loader.c M src/console/printk.c M src/include/console/console.h M src/lib/hardwaremain.c M src/lib/prog_loaders.c 5 files changed, 65 insertions(+), 0 deletions(-)
git pull ssh://review.coreboot.org:29418/coreboot refs/changes/74/36574/3
Hello build bot (Jenkins),
I'd like you to reexamine a change. Please visit
https://review.coreboot.org/c/coreboot/+/36574
to look at the new patch set (#4).
Change subject: [WIP] console,boot_state: Exclude printk() from reported times ......................................................................
[WIP] console,boot_state: Exclude printk() from reported times
Change-Id: Id3998bab553ff803a93257a3f2c7bfea44c31729 Signed-off-by: Kyösti Mälkki kyosti.malkki@gmail.com --- M src/arch/x86/postcar_loader.c M src/console/printk.c M src/include/console/console.h M src/lib/hardwaremain.c M src/lib/prog_loaders.c 5 files changed, 67 insertions(+), 0 deletions(-)
git pull ssh://review.coreboot.org:29418/coreboot refs/changes/74/36574/4
Hello build bot (Jenkins),
I'd like you to reexamine a change. Please visit
https://review.coreboot.org/c/coreboot/+/36574
to look at the new patch set (#5).
Change subject: console,boot_state: Exclude printk() from reported times ......................................................................
console,boot_state: Exclude printk() from reported times
Use monotonic timer to accumulate the time spent in console code.
For bootblock and romstage, only stage total is reported. For ramstage each boot_state is reported individually.
Change-Id: Id3998bab553ff803a93257a3f2c7bfea44c31729 Signed-off-by: Kyösti Mälkki kyosti.malkki@gmail.com --- M src/arch/x86/postcar_loader.c M src/console/printk.c M src/include/console/console.h M src/lib/hardwaremain.c M src/lib/prog_loaders.c 5 files changed, 67 insertions(+), 0 deletions(-)
git pull ssh://review.coreboot.org:29418/coreboot refs/changes/74/36574/5
Paul Menzel has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36574 )
Change subject: console,boot_state: Exclude printk() from reported times ......................................................................
Patch Set 5: Code-Review+1
Nico Huber has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/36574 )
Change subject: console,boot_state: Exclude printk() from reported times ......................................................................
Patch Set 5: Code-Review+2
(1 comment)
https://review.coreboot.org/c/coreboot/+/36574/5/src/console/printk.c File src/console/printk.c:
https://review.coreboot.org/c/coreboot/+/36574/5/src/console/printk.c@31 PS5, Line 31: !CONFIG(CAR_GLOBAL_MIGRATION) ooh, I like that :)
Patrick Georgi has submitted this change. ( https://review.coreboot.org/c/coreboot/+/36574 )
Change subject: console,boot_state: Exclude printk() from reported times ......................................................................
console,boot_state: Exclude printk() from reported times
Use monotonic timer to accumulate the time spent in console code.
For bootblock and romstage, only stage total is reported. For ramstage each boot_state is reported individually.
Change-Id: Id3998bab553ff803a93257a3f2c7bfea44c31729 Signed-off-by: Kyösti Mälkki kyosti.malkki@gmail.com Reviewed-on: https://review.coreboot.org/c/coreboot/+/36574 Tested-by: build bot (Jenkins) no-reply@coreboot.org Reviewed-by: Paul Menzel paulepanter@users.sourceforge.net Reviewed-by: Nico Huber nico.h@gmx.de --- M src/arch/x86/postcar_loader.c M src/console/printk.c M src/include/console/console.h M src/lib/hardwaremain.c M src/lib/prog_loaders.c 5 files changed, 67 insertions(+), 0 deletions(-)
Approvals: build bot (Jenkins): Verified Nico Huber: Looks good to me, approved Paul Menzel: Looks good to me, but someone else must approve
diff --git a/src/arch/x86/postcar_loader.c b/src/arch/x86/postcar_loader.c index 868b770..b53cbf8 100644 --- a/src/arch/x86/postcar_loader.c +++ b/src/arch/x86/postcar_loader.c @@ -228,6 +228,8 @@ /* As postcar exist, it's end of romstage here */ timestamp_add_now(TS_END_ROMSTAGE);
+ console_time_report(); + prog_set_arg(&prog, cbmem_top());
prog_run(&prog); diff --git a/src/console/printk.c b/src/console/printk.c index 15c599d..4f9f547 100644 --- a/src/console/printk.c +++ b/src/console/printk.c @@ -21,14 +21,56 @@ #include <smp/node.h> #include <stddef.h> #include <trace.h> +#include <timer.h>
#if (!defined(__PRE_RAM__) && CONFIG(HAVE_ROMSTAGE_CONSOLE_SPINLOCK)) || !CONFIG(HAVE_ROMSTAGE_CONSOLE_SPINLOCK) DECLARE_SPIN_LOCK(console_lock) #endif
+#define TRACK_CONSOLE_TIME (CONFIG(HAVE_MONOTONIC_TIMER) && \ + (ENV_RAMSTAGE || !CONFIG(CAR_GLOBAL_MIGRATION))) + +static struct mono_time mt_start, mt_stop; +static long console_usecs; + +static void console_time_run(void) +{ + if (TRACK_CONSOLE_TIME) + timer_monotonic_get(&mt_start); +} + +static void console_time_stop(void) +{ + if (TRACK_CONSOLE_TIME) { + timer_monotonic_get(&mt_stop); + console_usecs += mono_time_diff_microseconds(&mt_start, &mt_stop); + } +} + +void console_time_report(void) +{ + if (!TRACK_CONSOLE_TIME) + return; + + printk(BIOS_DEBUG, "Accumulated console time in " ENV_STRING " %ld ms\n", + DIV_ROUND_CLOSEST(console_usecs, USECS_PER_MSEC)); +} + +long console_time_get_and_reset(void) +{ + if (!TRACK_CONSOLE_TIME) + return 0; + + long elapsed = console_usecs; + console_usecs = 0; + return elapsed; +} + void do_putchar(unsigned char byte) { + console_time_run(); console_tx_byte(byte); + console_time_stop(); }
static void wrap_putchar(unsigned char byte, void *data) @@ -61,6 +103,8 @@ spin_lock(&console_lock); #endif
+ console_time_run(); + if (log_this == CONSOLE_LOG_FAST) { i = vtxprintf(wrap_putchar_cbmemc, fmt, args, NULL); } else { @@ -68,6 +112,8 @@ console_tx_flush(); }
+ console_time_stop(); + #ifdef __PRE_RAM__ #if CONFIG(HAVE_ROMSTAGE_CONSOLE_SPINLOCK) spin_unlock(romstage_console_lock()); diff --git a/src/include/console/console.h b/src/include/console/console.h index 1c2a276..607c968 100644 --- a/src/include/console/console.h +++ b/src/include/console/console.h @@ -64,6 +64,11 @@ int console_log_level(int msg_level); void do_putchar(unsigned char byte);
+/* Return number of microseconds elapsed from start of stage or the previous + get_and_reset() call. */ +long console_time_get_and_reset(void); +void console_time_report(void); + #define printk(LEVEL, fmt, args...) do_printk(LEVEL, fmt, ##args) #define vprintk(LEVEL, fmt, args) do_vprintk(LEVEL, fmt, args)
@@ -87,6 +92,8 @@ static inline void printk(int LEVEL, const char *fmt, ...) {} static inline void vprintk(int LEVEL, const char *fmt, va_list args) {} static inline void do_putchar(unsigned char byte) {} +static inline long console_time_get_and_reset(void) { return 0; } +static inline void console_time_report(void) {} #endif
int do_printk(int msg_level, const char *fmt, ...) diff --git a/src/lib/hardwaremain.c b/src/lib/hardwaremain.c index 51ff330..3fcf882 100644 --- a/src/lib/hardwaremain.c +++ b/src/lib/hardwaremain.c @@ -63,6 +63,7 @@ struct boot_state_times { int num_samples; struct mono_time samples[MAX_TIME_SAMPLES]; + long console_usecs[MAX_TIME_SAMPLES]; };
/* The prologue (BS_ON_ENTRY) and epilogue (BS_ON_EXIT) of a state can be @@ -241,6 +242,9 @@ { struct mono_time *mt;
+ long console_usecs = console_time_get_and_reset(); + state->times.console_usecs[state->times.num_samples] = console_usecs; + mt = &state->times.samples[state->times.num_samples]; timer_monotonic_get(mt); state->times.num_samples++; @@ -257,6 +261,10 @@ run_time = mono_time_diff_microseconds(&samples[1], &samples[2]); exit_time = mono_time_diff_microseconds(&samples[2], &samples[3]);
+ entry_time -= state->times.console_usecs[1]; + run_time -= state->times.console_usecs[2]; + exit_time -= state->times.console_usecs[3]; + /* Report with millisecond precision to reduce log diffs. */ entry_time = DIV_ROUND_CLOSEST(entry_time, USECS_PER_MSEC); run_time = DIV_ROUND_CLOSEST(run_time, USECS_PER_MSEC); diff --git a/src/lib/prog_loaders.c b/src/lib/prog_loaders.c index 72c1de1..43f4689 100644 --- a/src/lib/prog_loaders.c +++ b/src/lib/prog_loaders.c @@ -72,6 +72,8 @@
timestamp_add_now(TS_END_COPYROM);
+ console_time_report(); + prog_run(&romstage);
fail: @@ -155,6 +157,8 @@
timestamp_add_now(TS_END_COPYRAM);
+ console_time_report(); + /* This overrides the arg fetched from the relocatable module */ prog_set_arg(&ramstage, cbmem_top());
-
Kyösti Mälkki (Code Review) -
Nico Huber (Code Review)
-
Patrick Georgi (Code Review)
-
Paul Menzel (Code Review)