From a7d924412a4300e91b3bd6eb3581b954b02f8d37 Mon Sep 17 00:00:00 2001 From: Julius Werner Date: Tue, 2 Dec 2014 20:51:19 -0800 Subject: timestamps: You can never have enough of them! Now that we have timestamps in pre-RAM stages, let's actually make use of them. This patch adds several timestamps to both the bootblock and especially the verstage to allow more fine-grained boot time tracking. Some of the introduced timestamps can appear more than once per boot. This doesn't seem to be a problem for both coreboot and the cbmem utility, and the context makes it clear which operation was timestamped at what point. Also simplifies cbmem's timestamp printing routine a bit, fixing a display bug when a timestamp had a section of exactly ",000," in it (e.g. 1,000,185). BRANCH=None BUG=None TEST=Booted Pinky, Blaze and Falco, confirmed that all timestamps show up and contained sane values. Booted Storm (no timestamps here since it doesn't support pre-RAM timestamps yet). Change-Id: I7f4d6aba3ebe3db0d003c7bcb2954431b74961b3 Signed-off-by: Patrick Georgi Original-Commit-Id: 7a2ce81722aba85beefcc6c81f9908422b8da8fa Original-Change-Id: I5979bfa9445a9e0aba98ffdf8006c21096743456 Original-Signed-off-by: Julius Werner Original-Reviewed-on: https://chromium-review.googlesource.com/234063 Original-Reviewed-by: Aaron Durbin Reviewed-on: http://review.coreboot.org/9608 Tested-by: build bot (Jenkins) Reviewed-by: Stefan Reinauer --- util/cbmem/cbmem.c | 52 ++++++++++++++++++++++++++++++---------------------- 1 file changed, 30 insertions(+), 22 deletions(-) (limited to 'util') diff --git a/util/cbmem/cbmem.c b/util/cbmem/cbmem.c index 7c96c6e5ce..042159192b 100644 --- a/util/cbmem/cbmem.c +++ b/util/cbmem/cbmem.c @@ -334,24 +334,17 @@ u64 arch_convert_raw_ts_entry(u64 ts) /* * Print an integer in 'normalized' form - with commas separating every three - * decimal orders. The 'comma' parameter indicates if a comma is needed after - * the value is printed. + * decimal orders. */ -static void print_norm(u64 v, int comma) +static void print_norm(u64 v) { - int first_triple = 1; - - if (v > 1000) { + if (v >= 1000) { /* print the higher order sections first */ - print_norm(v / 1000, 1); - first_triple = 0; + print_norm(v / 1000); + printf(",%3.3u", (u32)(v % 1000)); + } else { + printf("%u", (u32)(v % 1000)); } - if (first_triple) - printf("%d", (u32)(v % 1000)); - else - printf("%3.3d", (u32)(v % 1000)); - if (comma) - printf(","); } enum additional_timestamp_id { @@ -381,11 +374,15 @@ static const struct timestamp_id_to_name { { TS_END_ROMSTAGE, "end of romstage" }, { TS_START_VBOOT, "start of verified boot" }, { TS_END_VBOOT, "end of verified boot" }, - { TS_START_COPYRAM, "start of copying ram stage" }, - { TS_END_COPYRAM, "end of copying ram stage" }, + { TS_START_COPYRAM, "starting to load ramstage" }, + { TS_END_COPYRAM, "finished loading ramstage" }, { TS_START_RAMSTAGE, "start of ramstage" }, - { TS_START_BOOTBLOCK, "start of bootblock" }, - { TS_END_BOOTBLOCK, "end of bootblock" }, + { TS_START_BOOTBLOCK, "start of bootblock" }, + { TS_END_BOOTBLOCK, "end of bootblock" }, + { TS_START_COPYROM, "starting to load romstage" }, + { TS_END_COPYROM, "finished loading romstage" }, + { TS_START_ULZMA, "starting LZMA decompress (ignore for x86)" }, + { TS_END_ULZMA, "finished LZMA decompress (ignore for x86)" }, { TS_DEVICE_ENUMERATE, "device enumeration" }, { TS_DEVICE_CONFIGURE, "device configuration" }, { TS_DEVICE_ENABLE, "device enable" }, @@ -396,6 +393,18 @@ static const struct timestamp_id_to_name { { TS_LOAD_PAYLOAD, "load payload" }, { TS_ACPI_WAKE_JUMP, "ACPI wake jump" }, { TS_SELFBOOT_JUMP, "selfboot jump" }, + + { TS_START_COPYVER, "starting to load verstage" }, + { TS_END_COPYVER, "finished loading verstage" }, + { TS_START_TPMINIT, "starting to initialize TPM" }, + { TS_END_TPMINIT, "finished TPM initialization" }, + { TS_START_VERIFY_SLOT, "starting to verify keyblock/preamble (RSA)" }, + { TS_END_VERIFY_SLOT, "finished verifying keyblock/preamble (RSA)" }, + { TS_START_HASH_BODY, "starting to verify body (load+SHA2+RSA) " }, + { TS_DONE_LOADING, "finished loading body (ignore for x86)" }, + { TS_DONE_HASHING, "finished calculating body hash (SHA2)" }, + { TS_END_HASH_BODY, "finished verifying body signature (RSA)" }, + { TS_DC_START, "depthcharge start" }, { TS_RO_PARAMS_INIT, "RO parameter init" }, { TS_RO_VB_INIT, "RO vboot init" }, @@ -421,12 +430,11 @@ void timestamp_print_entry(uint32_t id, uint64_t stamp, uint64_t prev_stamp) } printf("%4d:", id); - printf("%-30s", name); - print_norm(arch_convert_raw_ts_entry(stamp), 0); + printf("%-50s", name); + print_norm(arch_convert_raw_ts_entry(stamp)); if (prev_stamp) { printf(" ("); - print_norm(arch_convert_raw_ts_entry(stamp - - prev_stamp), 0); + print_norm(arch_convert_raw_ts_entry(stamp - prev_stamp)); printf(")"); } printf("\n"); -- cgit v1.2.3