Change in coreboot[4.11_branch]: Revert "console,boot_state: Exclude printk() from reported times"
Kyösti Mälkki has uploaded this change for review. ( https://review.coreboot.org/c/coreboot/+/37396 )
Change subject: Revert "console,boot_state: Exclude printk() from reported times" ......................................................................
Revert "console,boot_state: Exclude printk() from reported times"
This reverts commit 45ddb4344f73051855da6d4e87a5ba4b4c66af71.
This was witnessed to cause boot regressions together with LAPIC_MONOTONIC_TIMER=y. The code in cpu/x86/lapic/apic_timer.c for timer_monotonic_get() is not SMP safe as LAPIC timers do not run as synchronised as TSCs.
Since the approach for this improved times reporting was not completed for the format either, revert it from 4.11_branch.
Change-Id: Ie7edae572cf4fee0b9d2497f7690145c2699a809 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, 0 insertions(+), 67 deletions(-)
git pull ssh://review.coreboot.org:29418/coreboot refs/changes/96/37396/1
diff --git a/src/arch/x86/postcar_loader.c b/src/arch/x86/postcar_loader.c index b53cbf8..868b770 100644 --- a/src/arch/x86/postcar_loader.c +++ b/src/arch/x86/postcar_loader.c @@ -228,8 +228,6 @@ /* 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 4f9f547..15c599d 100644 --- a/src/console/printk.c +++ b/src/console/printk.c @@ -21,56 +21,14 @@ #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) @@ -103,8 +61,6 @@ spin_lock(&console_lock); #endif
- console_time_run(); - if (log_this == CONSOLE_LOG_FAST) { i = vtxprintf(wrap_putchar_cbmemc, fmt, args, NULL); } else { @@ -112,8 +68,6 @@ 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 607c968..1c2a276 100644 --- a/src/include/console/console.h +++ b/src/include/console/console.h @@ -64,11 +64,6 @@ 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)
@@ -92,8 +87,6 @@ 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 3fcf882..51ff330 100644 --- a/src/lib/hardwaremain.c +++ b/src/lib/hardwaremain.c @@ -63,7 +63,6 @@ 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 @@ -242,9 +241,6 @@ { 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++; @@ -261,10 +257,6 @@ 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 5787496..7f320d9 100644 --- a/src/lib/prog_loaders.c +++ b/src/lib/prog_loaders.c @@ -70,8 +70,6 @@
timestamp_add_now(TS_END_COPYROM);
- console_time_report(); - prog_run(&romstage);
fail: @@ -155,8 +153,6 @@
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 has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/37396 )
Change subject: Revert "console,boot_state: Exclude printk() from reported times" ......................................................................
Patch Set 1:
Here's the regression discovered in pcengines/apu2 log:
CPU_CLUSTER: 0 init ... ... CPU 0x02 would not start! CPU 0x02 did not initialize! CPU_CLUSTER: 0 init finished in 65560584 usecs (<= should be ~130ms) ... BS: BS_DEV_INIT times (ms): entry 0 run 65530 exit 0
Angel Pons has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/37396 )
Change subject: Revert "console,boot_state: Exclude printk() from reported times" ......................................................................
Patch Set 1: Code-Review+2
Werner Zeh has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/37396 )
Change subject: Revert "console,boot_state: Exclude printk() from reported times" ......................................................................
Patch Set 1: Code-Review+2
Frans Hendriks has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/37396 )
Change subject: Revert "console,boot_state: Exclude printk() from reported times" ......................................................................
Patch Set 1: Code-Review+1
Kyösti Mälkki has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/37396 )
Change subject: Revert "console,boot_state: Exclude printk() from reported times" ......................................................................
Patch Set 1: Code-Review-2
This will go in ultimately (reports wrong time) but regression is somewhere else.
Hello Werner Zeh, Angel Pons, Frans Hendriks, Patrick Rudolph, David Hendricks, build bot (Jenkins), Michał Żygowski,
I'd like you to reexamine a change. Please visit
https://review.coreboot.org/c/coreboot/+/37396
to look at the new patch set (#2).
Change subject: Revert "console,boot_state: Exclude printk() from reported times" ......................................................................
Revert "console,boot_state: Exclude printk() from reported times"
The code in cpu/x86/lapic/apic_timer.c for timer_monotonic_get() is not SMP safe as LAPIC timers do not run as synchronised as TSCs. So the reported times with LAPIC_MONOTONIC_TIMER=n at least were incorrect.
Since the approach for this improved times reporting was not completed wrt. the output format either, revert it from 4.11_branch.
Change-Id: Ie7edae572cf4fee0b9d2497f7690145c2699a809 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, 0 insertions(+), 67 deletions(-)
git pull ssh://review.coreboot.org:29418/coreboot refs/changes/96/37396/2
Kyösti Mälkki has posted comments on this change. ( https://review.coreboot.org/c/coreboot/+/37396 )
Change subject: Revert "console,boot_state: Exclude printk() from reported times" ......................................................................
Patch Set 2: -Code-Review
The real regression of CPU #2/#3 not starting was elsewhere and reference to that are now removed from the commmit message.
Hello Werner Zeh, Angel Pons, Frans Hendriks, Patrick Rudolph, David Hendricks, build bot (Jenkins), Michał Żygowski,
I'd like you to reexamine a change. Please visit
https://review.coreboot.org/c/coreboot/+/37396
to look at the new patch set (#3).
Change subject: Revert "console,boot_state: Exclude printk() from reported times" ......................................................................
Revert "console,boot_state: Exclude printk() from reported times"
The code in cpu/x86/lapic/apic_timer.c for timer_monotonic_get() is not SMP safe as LAPIC timers do not run as synchronised as TSCs. So the reported times with LAPIC_MONOTONIC_TIMER=y at least were incorrect.
Since the approach for this improved times reporting was not completed wrt. the output format either, revert it from 4.11_branch.
Change-Id: Ie7edae572cf4fee0b9d2497f7690145c2699a809 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, 0 insertions(+), 67 deletions(-)
git pull ssh://review.coreboot.org:29418/coreboot refs/changes/96/37396/3
Hello Werner Zeh, Angel Pons, Frans Hendriks, Patrick Rudolph, David Hendricks, build bot (Jenkins), Michał Żygowski,
I'd like you to reexamine a change. Please visit
https://review.coreboot.org/c/coreboot/+/37396
to look at the new patch set (#4).
Change subject: Revert "console,boot_state: Exclude printk() from reported times" ......................................................................
Revert "console,boot_state: Exclude printk() from reported times"
The code in cpu/x86/lapic/apic_timer.c for timer_monotonic_get() is not SMP safe as LAPIC timers do not run as synchronised as TSCs. So the reported times with LAPIC_MONOTONIC_TIMER=y at least were incorrect.
Since the approach for this improved times reporting was not completed wrt. the output format either, revert it from 4.11_branch.
Change-Id: Ie7edae572cf4fee0b9d2497f7690145c2699a809 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, 0 insertions(+), 67 deletions(-)
git pull ssh://review.coreboot.org:29418/coreboot refs/changes/96/37396/4
Kyösti Mälkki has submitted this change. ( https://review.coreboot.org/c/coreboot/+/37396 )
Change subject: Revert "console,boot_state: Exclude printk() from reported times" ......................................................................
Revert "console,boot_state: Exclude printk() from reported times"
The code in cpu/x86/lapic/apic_timer.c for timer_monotonic_get() is not SMP safe as LAPIC timers do not run as synchronised as TSCs. So the reported times with LAPIC_MONOTONIC_TIMER=y at least were incorrect.
Since the approach for this improved times reporting was not completed wrt. the output format either, revert it from 4.11_branch.
Change-Id: Ie7edae572cf4fee0b9d2497f7690145c2699a809 Signed-off-by: Kyösti Mälkki kyosti.malkki@gmail.com Reviewed-on: https://review.coreboot.org/c/coreboot/+/37396 Tested-by: build bot (Jenkins) no-reply@coreboot.org Reviewed-by: Angel Pons th3fanbus@gmail.com Reviewed-by: Werner Zeh werner.zeh@siemens.com Reviewed-by: Frans Hendriks fhendriks@eltan.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, 0 insertions(+), 67 deletions(-)
Approvals: build bot (Jenkins): Verified Werner Zeh: Looks good to me, approved Frans Hendriks: Looks good to me, but someone else must approve Angel Pons: Looks good to me, approved
diff --git a/src/arch/x86/postcar_loader.c b/src/arch/x86/postcar_loader.c index b53cbf8..868b770 100644 --- a/src/arch/x86/postcar_loader.c +++ b/src/arch/x86/postcar_loader.c @@ -228,8 +228,6 @@ /* 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 4f9f547..15c599d 100644 --- a/src/console/printk.c +++ b/src/console/printk.c @@ -21,56 +21,14 @@ #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) @@ -103,8 +61,6 @@ spin_lock(&console_lock); #endif
- console_time_run(); - if (log_this == CONSOLE_LOG_FAST) { i = vtxprintf(wrap_putchar_cbmemc, fmt, args, NULL); } else { @@ -112,8 +68,6 @@ 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 607c968..1c2a276 100644 --- a/src/include/console/console.h +++ b/src/include/console/console.h @@ -64,11 +64,6 @@ 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)
@@ -92,8 +87,6 @@ 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 3fcf882..51ff330 100644 --- a/src/lib/hardwaremain.c +++ b/src/lib/hardwaremain.c @@ -63,7 +63,6 @@ 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 @@ -242,9 +241,6 @@ { 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++; @@ -261,10 +257,6 @@ 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 5787496..7f320d9 100644 --- a/src/lib/prog_loaders.c +++ b/src/lib/prog_loaders.c @@ -70,8 +70,6 @@
timestamp_add_now(TS_END_COPYROM);
- console_time_report(); - prog_run(&romstage);
fail: @@ -155,8 +153,6 @@
timestamp_add_now(TS_END_COPYRAM);
- console_time_report(); - /* This overrides the arg fetched from the relocatable module */ prog_set_arg(&ramstage, cbmem_top());
-
Angel Pons (Code Review) -
Frans Hendriks (Code Review)
-
Kyösti Mälkki (Code Review)
-
Werner Zeh (Code Review)