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>

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());