From cb4287423150179da5a744884830e4abaae9a66f Mon Sep 17 00:00:00 2001 From: Raul E Rangel Date: Wed, 9 Jun 2021 16:49:53 -0600 Subject: lib/hardwaremain: Print individual boot state callback durations This is useful when trying to find which callbacks are taking the longest time. BUG=b:179092979 TEST=See bootstate durations in logs BS: callback (0xcb79d4d8) @ src/security/vboot/bootmode.c:53 (0 ms). BS: callback (0xcb79cf20) @ src/vendorcode/google/chromeos/ramoops.c:30 (0 ms). BS: callback (0xcb79cef0) @ src/vendorcode/google/chromeos/cr50_enable_update.c:160 (18 ms). Signed-off-by: Raul E Rangel Change-Id: Ifb145fea32ad4e0b694bdb7cdcdd43dce4cc0d27 Reviewed-on: https://review.coreboot.org/c/coreboot/+/55374 Reviewed-by: Angel Pons Reviewed-by: Julius Werner Tested-by: build bot (Jenkins) --- src/lib/hardwaremain.c | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/src/lib/hardwaremain.c b/src/lib/hardwaremain.c index 7ab2ade912..90c910a320 100644 --- a/src/lib/hardwaremain.c +++ b/src/lib/hardwaremain.c @@ -264,6 +264,7 @@ static void bs_call_callbacks(struct boot_state *state, boot_state_sequence_t seq) { struct boot_phase *phase = &state->phases[seq]; + struct mono_time mt_start, mt_stop; while (1) { if (phase->callbacks != NULL) { @@ -277,8 +278,16 @@ static void bs_call_callbacks(struct boot_state *state, if (CONFIG(DEBUG_BOOT_STATE)) { printk(BIOS_DEBUG, "BS: callback (%p) @ %s.\n", bscb, bscb_location(bscb)); + timer_monotonic_get(&mt_start); } bscb->callback(bscb->arg); + if (CONFIG(DEBUG_BOOT_STATE)) { + timer_monotonic_get(&mt_stop); + printk(BIOS_DEBUG, "BS: callback (%p) @ %s (%ld ms).\n", bscb, + bscb_location(bscb), + mono_time_diff_microseconds(&mt_start, &mt_stop) + / USECS_PER_MSEC); + } continue; } -- cgit v1.2.3