From 94694a810e752760ba18d1cf545c63ff3287092b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ky=C3=B6sti=20M=C3=A4lkki?= Date: Sat, 2 Nov 2019 18:14:31 +0200 Subject: console,boot_state: Reformat state times output MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit For each boot_state, report the times spent interleaved with other console output and remove the samples arrays. The time spent to report the times to console is not accounted for. Change-Id: I0c847da98901c56b356b4a933d9ae865dada98b6 Signed-off-by: Kyösti Mälkki Reviewed-on: https://review.coreboot.org/c/coreboot/+/36584 Tested-by: build bot (Jenkins) Reviewed-by: Nico Huber --- src/console/printk.c | 2 +- src/lib/hardwaremain.c | 91 +++++++++++++++++++------------------------------- 2 files changed, 36 insertions(+), 57 deletions(-) diff --git a/src/console/printk.c b/src/console/printk.c index b32fadb8b1..3ef28f32be 100644 --- a/src/console/printk.c +++ b/src/console/printk.c @@ -49,7 +49,7 @@ void console_time_report(void) if (!TRACK_CONSOLE_TIME) return; - printk(BIOS_DEBUG, "Accumulated console time in " ENV_STRING " %ld ms\n", + printk(BIOS_DEBUG, "BS: " ENV_STRING " times (exec / console): total (unknown) / %ld ms\n", DIV_ROUND_CLOSEST(console_usecs, USECS_PER_MSEC)); } diff --git a/src/lib/hardwaremain.c b/src/lib/hardwaremain.c index 3fcf8829f3..eba5f12625 100644 --- a/src/lib/hardwaremain.c +++ b/src/lib/hardwaremain.c @@ -52,20 +52,6 @@ static boot_state_t bs_write_tables(void *arg); static boot_state_t bs_payload_load(void *arg); static boot_state_t bs_payload_boot(void *arg); -/* - * Typically a state will take 4 time samples: - * 1. Before state entry callbacks - * 2. After state entry callbacks / Before state function. - * 3. After state function / Before state exit callbacks. - * 4. After state exit callbacks. - */ -#define MAX_TIME_SAMPLES 4 -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 * blocked from transitioning to the next (state,seq) pair. When the blockers * field is 0 a transition may occur. */ @@ -81,10 +67,8 @@ struct boot_state { struct boot_phase phases[2]; boot_state_t (*run_state)(void *arg); void *arg; + int num_samples; int complete : 1; -#if CONFIG(HAVE_MONOTONIC_TIMER) - struct boot_state_times times; -#endif }; #define BS_INIT(state_, run_func_) \ @@ -237,46 +221,43 @@ static boot_state_t bs_payload_boot(void *arg) return BS_PAYLOAD_BOOT; } -#if CONFIG(HAVE_MONOTONIC_TIMER) +/* + * Typically a state will take 4 time samples: + * 1. Before state entry callbacks + * 2. After state entry callbacks / Before state function. + * 3. After state function / Before state exit callbacks. + * 4. After state exit callbacks. + */ 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++; -} - -static void bs_report_time(struct boot_state *state) -{ - long entry_time; - long run_time; - long exit_time; - struct mono_time *samples = &state->times.samples[0]; - - entry_time = mono_time_diff_microseconds(&samples[0], &samples[1]); - 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); - exit_time = DIV_ROUND_CLOSEST(exit_time, USECS_PER_MSEC); - - printk(BIOS_DEBUG, "BS: %s times (ms): entry %ld run %ld exit %ld\n", - state->name, entry_time, run_time, exit_time); + static const char *const sample_id[] = { "entry", "run", "exit" }; + static struct mono_time previous_sample; + struct mono_time this_sample; + long console; + + if (!CONFIG(HAVE_MONOTONIC_TIMER)) + return; + + console = console_time_get_and_reset(); + timer_monotonic_get(&this_sample); + state->num_samples++; + + int i = state->num_samples - 2; + if ((i >= 0) && (i < ARRAY_SIZE(sample_id))) { + long execution = mono_time_diff_microseconds(&previous_sample, &this_sample); + + /* Report with millisecond precision to reduce log diffs. */ + execution = DIV_ROUND_CLOSEST(execution, USECS_PER_MSEC); + console = DIV_ROUND_CLOSEST(console, USECS_PER_MSEC); + if (execution) { + printk(BIOS_DEBUG, "BS: %s %s times (exec / console): %ld / %ld ms\n", + state->name, sample_id[i], execution - console, console); + /* Reset again to ignore printk() time above. */ + console_time_get_and_reset(); + } + } + timer_monotonic_get(&previous_sample); } -#else -static inline void bs_sample_time(struct boot_state *state) {} -static inline void bs_report_time(struct boot_state *state) {} -#endif #if CONFIG(TIMER_QUEUE) static void bs_run_timers(int drain) @@ -388,8 +369,6 @@ static void bs_walk_state_machine(void) bs_sample_time(state); - bs_report_time(state); - state->complete = 1; } } -- cgit v1.2.3