diff options
| -rw-r--r-- | src/arch/x86/postcar_loader.c | 2 | ||||
| -rw-r--r-- | src/console/printk.c | 46 | ||||
| -rw-r--r-- | src/include/console/console.h | 7 | ||||
| -rw-r--r-- | src/lib/hardwaremain.c | 8 | ||||
| -rw-r--r-- | src/lib/prog_loaders.c | 4 |
5 files changed, 67 insertions, 0 deletions
diff --git a/src/arch/x86/postcar_loader.c b/src/arch/x86/postcar_loader.c index 868b770c18..b53cbf82af 100644 --- a/src/arch/x86/postcar_loader.c +++ b/src/arch/x86/postcar_loader.c @@ -228,6 +228,8 @@ void run_postcar_phase(struct postcar_frame *pcf) /* 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 15c599dce0..4f9f547bc5 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 @@ int do_vprintk(int msg_level, const char *fmt, va_list args) 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 @@ int do_vprintk(int msg_level, const char *fmt, va_list args) 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 1c2a276af0..607c96862e 100644 --- a/src/include/console/console.h +++ b/src/include/console/console.h @@ -64,6 +64,11 @@ asmlinkage void console_init(void); 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 int console_log_level(int msg_level) { return 0; } 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 51ff330d84..3fcf8829f3 100644 --- a/src/lib/hardwaremain.c +++ b/src/lib/hardwaremain.c @@ -63,6 +63,7 @@ static boot_state_t bs_payload_boot(void *arg); 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 @@ static void bs_sample_time(struct boot_state *state) { 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 @@ static void bs_report_time(struct boot_state *state) 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 72c1de1e34..43f4689940 100644 --- a/src/lib/prog_loaders.c +++ b/src/lib/prog_loaders.c @@ -72,6 +72,8 @@ void run_romstage(void) timestamp_add_now(TS_END_COPYROM); + console_time_report(); + prog_run(&romstage); fail: @@ -155,6 +157,8 @@ void run_ramstage(void) timestamp_add_now(TS_END_COPYRAM); + console_time_report(); + /* This overrides the arg fetched from the relocatable module */ prog_set_arg(&ramstage, cbmem_top()); |