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 <rrangel@chromium.org>
Change-Id: Ifb145fea32ad4e0b694bdb7cdcdd43dce4cc0d27
Reviewed-on: https://review.coreboot.org/c/coreboot/+/55374
Reviewed-by: Angel Pons <th3fanbus@gmail.com>
Reviewed-by: Julius Werner <jwerner@chromium.org>
Tested-by: build bot (Jenkins) <no-reply@coreboot.org>
diff --git a/src/lib/hardwaremain.c b/src/lib/hardwaremain.c
index 7ab2ade..90c910a 100644
--- a/src/lib/hardwaremain.c
+++ b/src/lib/hardwaremain.c
@@ -264,6 +264,7 @@
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 @@
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;
}