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>
This commit is contained in:
Kyösti Mälkki 2019-11-02 14:12:18 +02:00 committed by Patrick Georgi
parent 19825e8e37
commit 45ddb4344f
5 changed files with 67 additions and 0 deletions

View File

@ -228,6 +228,8 @@ void run_postcar_phase(struct postcar_frame *pcf)
/* As postcar exist, it's end of romstage here */ /* As postcar exist, it's end of romstage here */
timestamp_add_now(TS_END_ROMSTAGE); timestamp_add_now(TS_END_ROMSTAGE);
console_time_report();
prog_set_arg(&prog, cbmem_top()); prog_set_arg(&prog, cbmem_top());
prog_run(&prog); prog_run(&prog);

View File

@ -21,14 +21,56 @@
#include <smp/node.h> #include <smp/node.h>
#include <stddef.h> #include <stddef.h>
#include <trace.h> #include <trace.h>
#include <timer.h>
#if (!defined(__PRE_RAM__) && CONFIG(HAVE_ROMSTAGE_CONSOLE_SPINLOCK)) || !CONFIG(HAVE_ROMSTAGE_CONSOLE_SPINLOCK) #if (!defined(__PRE_RAM__) && CONFIG(HAVE_ROMSTAGE_CONSOLE_SPINLOCK)) || !CONFIG(HAVE_ROMSTAGE_CONSOLE_SPINLOCK)
DECLARE_SPIN_LOCK(console_lock) DECLARE_SPIN_LOCK(console_lock)
#endif #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) void do_putchar(unsigned char byte)
{ {
console_time_run();
console_tx_byte(byte); console_tx_byte(byte);
console_time_stop();
} }
static void wrap_putchar(unsigned char byte, void *data) 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); spin_lock(&console_lock);
#endif #endif
console_time_run();
if (log_this == CONSOLE_LOG_FAST) { if (log_this == CONSOLE_LOG_FAST) {
i = vtxprintf(wrap_putchar_cbmemc, fmt, args, NULL); i = vtxprintf(wrap_putchar_cbmemc, fmt, args, NULL);
} else { } else {
@ -68,6 +112,8 @@ int do_vprintk(int msg_level, const char *fmt, va_list args)
console_tx_flush(); console_tx_flush();
} }
console_time_stop();
#ifdef __PRE_RAM__ #ifdef __PRE_RAM__
#if CONFIG(HAVE_ROMSTAGE_CONSOLE_SPINLOCK) #if CONFIG(HAVE_ROMSTAGE_CONSOLE_SPINLOCK)
spin_unlock(romstage_console_lock()); spin_unlock(romstage_console_lock());

View File

@ -64,6 +64,11 @@ asmlinkage void console_init(void);
int console_log_level(int msg_level); int console_log_level(int msg_level);
void do_putchar(unsigned char byte); 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 printk(LEVEL, fmt, args...) do_printk(LEVEL, fmt, ##args)
#define vprintk(LEVEL, fmt, args) do_vprintk(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 printk(int LEVEL, const char *fmt, ...) {}
static inline void vprintk(int LEVEL, const char *fmt, va_list args) {} static inline void vprintk(int LEVEL, const char *fmt, va_list args) {}
static inline void do_putchar(unsigned char byte) {} 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 #endif
int do_printk(int msg_level, const char *fmt, ...) int do_printk(int msg_level, const char *fmt, ...)

View File

@ -63,6 +63,7 @@ static boot_state_t bs_payload_boot(void *arg);
struct boot_state_times { struct boot_state_times {
int num_samples; int num_samples;
struct mono_time samples[MAX_TIME_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 /* 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; 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]; mt = &state->times.samples[state->times.num_samples];
timer_monotonic_get(mt); timer_monotonic_get(mt);
state->times.num_samples++; 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]); run_time = mono_time_diff_microseconds(&samples[1], &samples[2]);
exit_time = mono_time_diff_microseconds(&samples[2], &samples[3]); 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. */ /* Report with millisecond precision to reduce log diffs. */
entry_time = DIV_ROUND_CLOSEST(entry_time, USECS_PER_MSEC); entry_time = DIV_ROUND_CLOSEST(entry_time, USECS_PER_MSEC);
run_time = DIV_ROUND_CLOSEST(run_time, USECS_PER_MSEC); run_time = DIV_ROUND_CLOSEST(run_time, USECS_PER_MSEC);

View File

@ -72,6 +72,8 @@ void run_romstage(void)
timestamp_add_now(TS_END_COPYROM); timestamp_add_now(TS_END_COPYROM);
console_time_report();
prog_run(&romstage); prog_run(&romstage);
fail: fail:
@ -155,6 +157,8 @@ void run_ramstage(void)
timestamp_add_now(TS_END_COPYRAM); timestamp_add_now(TS_END_COPYRAM);
console_time_report();
/* This overrides the arg fetched from the relocatable module */ /* This overrides the arg fetched from the relocatable module */
prog_set_arg(&ramstage, cbmem_top()); prog_set_arg(&ramstage, cbmem_top());