drivers/elog/elog: Add timestamps to elog_init

elog init requires doing a lot of SPI transactions. This change makes it
clear how long we spend initializing elog.

BUG=b:179699789
TEST=Boot guybrush and see elog init timestamps
 114:started elog init                                3,029,116 (88)
 115:finished elog init                               3,071,281 (42,165)

Signed-off-by: Raul E Rangel <rrangel@chromium.org>
Change-Id: Ia92372dd76535e06eb3b8a08b53e80ddb38b7a8f
Reviewed-on: https://review.coreboot.org/c/coreboot/+/58957
Reviewed-by: Tim Wawrzynczak <twawrzynczak@chromium.org>
Tested-by: build bot (Jenkins) <no-reply@coreboot.org>
This commit is contained in:
Raul E Rangel 2021-11-03 16:53:40 -06:00 committed by Paul Fagerburg
parent 61c9cd9890
commit dc45951e88
2 changed files with 12 additions and 0 deletions

View File

@ -56,6 +56,8 @@ enum timestamp_id {
TS_DELAY_END = 111, TS_DELAY_END = 111,
TS_READ_UCODE_START = 112, TS_READ_UCODE_START = 112,
TS_READ_UCODE_END = 113, TS_READ_UCODE_END = 113,
TS_ELOG_INIT_START = 114,
TS_ELOG_INIT_END = 115,
/* 500+ reserved for vendorcode extensions (500-600: google/chromeos) */ /* 500+ reserved for vendorcode extensions (500-600: google/chromeos) */
TS_START_COPYVER = 501, TS_START_COPYVER = 501,
@ -200,6 +202,8 @@ static const struct timestamp_id_to_name {
{ TS_DELAY_END, "Forced delay end" }, { TS_DELAY_END, "Forced delay end" },
{ TS_READ_UCODE_START, "started reading uCode" }, { TS_READ_UCODE_START, "started reading uCode" },
{ TS_READ_UCODE_END, "finished reading uCode" }, { TS_READ_UCODE_END, "finished reading uCode" },
{ TS_ELOG_INIT_START, "started elog init" },
{ TS_ELOG_INIT_END, "finished elog init" },
{ TS_START_COPYVER, "starting to load verstage" }, { TS_START_COPYVER, "starting to load verstage" },
{ TS_END_COPYVER, "finished loading verstage" }, { TS_END_COPYVER, "finished loading verstage" },

View File

@ -16,6 +16,7 @@
#include <smbios.h> #include <smbios.h>
#include <stdint.h> #include <stdint.h>
#include <string.h> #include <string.h>
#include <timestamp.h>
#define ELOG_MIN_AVAILABLE_ENTRIES 2 /* Shrink when this many can't fit */ #define ELOG_MIN_AVAILABLE_ENTRIES 2 /* Shrink when this many can't fit */
#define ELOG_SHRINK_PERCENTAGE 25 /* Percent of total area to remove */ #define ELOG_SHRINK_PERCENTAGE 25 /* Percent of total area to remove */
@ -749,6 +750,9 @@ int elog_init(void)
} }
elog_state.elog_initialized = ELOG_BROKEN; elog_state.elog_initialized = ELOG_BROKEN;
if (!ENV_SMM)
timestamp_add_now(TS_ELOG_INIT_START);
elog_debug("%s()\n", __func__); elog_debug("%s()\n", __func__);
/* Set up the backing store */ /* Set up the backing store */
@ -781,6 +785,10 @@ int elog_init(void)
if (ENV_PAYLOAD_LOADER) if (ENV_PAYLOAD_LOADER)
elog_add_boot_count(); elog_add_boot_count();
if (!ENV_SMM)
timestamp_add_now(TS_ELOG_INIT_END);
return 0; return 0;
} }