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 --- src/include/timestamp.h | 18 ++++++++ src/lib/loaders/load_and_run_romstage.c | 3 ++ src/lib/lzma.c | 4 ++ src/lib/timestamp.c | 2 +- .../google/chromeos/vboot2/vboot_handoff.c | 6 ++- src/vendorcode/google/chromeos/vboot2/verstage.c | 36 +++++++++++++-- src/vendorcode/google/chromeos/vboot2/verstub.c | 26 ++++++----- util/cbmem/cbmem.c | 52 +++++++++++++--------- 8 files changed, 108 insertions(+), 39 deletions(-) diff --git a/src/include/timestamp.h b/src/include/timestamp.h index c2bc6f148f..cd648ea00b 100644 --- a/src/include/timestamp.h +++ b/src/include/timestamp.h @@ -46,6 +46,10 @@ enum timestamp_id { TS_START_RAMSTAGE = 10, TS_START_BOOTBLOCK = 11, TS_END_BOOTBLOCK = 12, + TS_START_COPYROM = 13, + TS_END_COPYROM = 14, + TS_START_ULZMA = 15, + TS_END_ULZMA = 16, TS_DEVICE_ENUMERATE = 30, TS_FSP_BEFORE_ENUMERATE, TS_FSP_AFTER_ENUMERATE, @@ -60,6 +64,20 @@ enum timestamp_id { TS_LOAD_PAYLOAD = 90, TS_ACPI_WAKE_JUMP = 98, TS_SELFBOOT_JUMP = 99, + + /* 500+ reserved for vendorcode extensions (500-600: google/chromeos) */ + TS_START_COPYVER = 501, + TS_END_COPYVER = 502, + TS_START_TPMINIT = 503, + TS_END_TPMINIT = 504, + TS_START_VERIFY_SLOT = 505, + TS_END_VERIFY_SLOT = 506, + TS_START_HASH_BODY = 507, + TS_DONE_LOADING = 508, + TS_DONE_HASHING = 509, + TS_END_HASH_BODY = 510, + + /* 1000+ reserved for payloads (1000-1200: ChromeOS depthcharge) */ }; #if CONFIG_COLLECT_TIMESTAMPS && (CONFIG_EARLY_CBMEM_INIT || !defined(__PRE_RAM__)) diff --git a/src/lib/loaders/load_and_run_romstage.c b/src/lib/loaders/load_and_run_romstage.c index 8467e90129..9bd9603bab 100644 --- a/src/lib/loaders/load_and_run_romstage.c +++ b/src/lib/loaders/load_and_run_romstage.c @@ -24,6 +24,7 @@ #include #include #include +#include void run_romstage(void) { @@ -32,11 +33,13 @@ void run_romstage(void) .type = PROG_ROMSTAGE, }; + timestamp_add_now(TS_START_COPYROM); if (cbfs_load_prog_stage(CBFS_DEFAULT_MEDIA, &romstage) < 0) { if (IS_ENABLED(CONFIG_BOOTBLOCK_CONSOLE)) die("Couldn't load romstage.\n"); halt(); } + timestamp_add_now(TS_END_COPYROM); prog_run(&romstage); } diff --git a/src/lib/lzma.c b/src/lib/lzma.c index 8efa1e6e1a..89e4d97600 100644 --- a/src/lib/lzma.c +++ b/src/lib/lzma.c @@ -12,6 +12,7 @@ #include #include #include +#include #include "lzmadecode.h" @@ -27,6 +28,8 @@ unsigned long ulzma(unsigned char * src, unsigned char * dst) MAYBE_STATIC unsigned char scratchpad[15980]; unsigned char *cp; + /* Note: these timestamps aren't useful for memory-mapped media (x86) */ + timestamp_add_now(TS_START_ULZMA); memcpy(properties, src, LZMA_PROPERTIES_SIZE); /* The outSize in LZMA stream is a 64bit integer stored in little-endian * (ref: lzma.cc@LZMACompress: put_64). To prevent accessing by @@ -50,5 +53,6 @@ unsigned long ulzma(unsigned char * src, unsigned char * dst) printk(BIOS_WARNING, "lzma: Decoding error = %d\n", res); return 0; } + timestamp_add_now(TS_END_ULZMA); return outSize; } diff --git a/src/lib/timestamp.c b/src/lib/timestamp.c index 67635f87ed..5846781706 100644 --- a/src/lib/timestamp.c +++ b/src/lib/timestamp.c @@ -25,7 +25,7 @@ #include #include -#define MAX_TIMESTAMPS 30 +#define MAX_TIMESTAMPS 60 static struct timestamp_table* ts_table_p CAR_GLOBAL = NULL; static uint64_t ts_basetime CAR_GLOBAL = 0; diff --git a/src/vendorcode/google/chromeos/vboot2/vboot_handoff.c b/src/vendorcode/google/chromeos/vboot2/vboot_handoff.c index 7e91432029..a5c7de617c 100644 --- a/src/vendorcode/google/chromeos/vboot2/vboot_handoff.c +++ b/src/vendorcode/google/chromeos/vboot2/vboot_handoff.c @@ -40,6 +40,7 @@ static void *load_ramstage(struct vboot_handoff *vboot_handoff, struct vboot_region *fw_main) { struct vboot_components *fw_info; + void *ret; int i; fw_info = vboot_locate_components(fw_main); @@ -53,7 +54,10 @@ static void *load_ramstage(struct vboot_handoff *vboot_handoff, vboot_handoff->components[i].size = fw_info->entries[i].size; } - return vboot_load_stage(CONFIG_VBOOT_RAMSTAGE_INDEX, fw_main, fw_info); + timestamp_add_now(TS_START_COPYRAM); + ret = vboot_load_stage(CONFIG_VBOOT_RAMSTAGE_INDEX, fw_main, fw_info); + timestamp_add_now(TS_END_COPYRAM); + return ret; } /** diff --git a/src/vendorcode/google/chromeos/vboot2/verstage.c b/src/vendorcode/google/chromeos/vboot2/verstage.c index 289b93fefc..569e6e569c 100644 --- a/src/vendorcode/google/chromeos/vboot2/verstage.c +++ b/src/vendorcode/google/chromeos/vboot2/verstage.c @@ -21,7 +21,9 @@ #include #include #include +#include #include +#include #include #include "../chromeos.h" @@ -91,12 +93,22 @@ int vb2ex_read_resource(struct vb2_context *ctx, static int hash_body(struct vb2_context *ctx, struct vboot_region *fw_main) { + uint64_t load_ts; uint32_t expected_size; MAYBE_STATIC uint8_t block[TODO_BLOCK_SIZE]; size_t block_size = sizeof(block); uintptr_t offset; int rv; + /* + * Since loading the firmware and calculating its hash is intertwined, + * we use this little trick to measure them separately and pretend it + * was first loaded and then hashed in one piece with the timestamps. + * (This split won't make sense with memory-mapped media like on x86.) + */ + load_ts = timestamp_get(); + timestamp_add(TS_START_HASH_BODY, load_ts); + expected_size = fw_main->size; offset = fw_main->offset_addr; @@ -107,13 +119,17 @@ static int hash_body(struct vb2_context *ctx, struct vboot_region *fw_main) /* Extend over the body */ while (expected_size) { + uint64_t temp_ts; void *b; if (block_size > expected_size) block_size = expected_size; + temp_ts = timestamp_get(); b = vboot_get_region(offset, block_size, block); if (b == NULL) return VB2_ERROR_UNKNOWN; + load_ts += timestamp_get() - temp_ts; + rv = vb2api_extend_hash(ctx, b, block_size); if (rv) return rv; @@ -122,11 +138,16 @@ static int hash_body(struct vb2_context *ctx, struct vboot_region *fw_main) offset += block_size; } - /* Check the result */ + timestamp_add(TS_DONE_LOADING, load_ts); + timestamp_add_now(TS_DONE_HASHING); + + /* Check the result (with RSA signature verification) */ rv = vb2api_check_hash(ctx); if (rv) return rv; + timestamp_add_now(TS_END_HASH_BODY); + return VB2_SUCCESS; } @@ -173,6 +194,7 @@ void verstage_main(void) struct vboot_region fw_main; struct vb2_working_data *wd = vboot_get_working_data(); int rv; + timestamp_add_now(TS_START_VBOOT); /* Set up context and work buffer */ memset(&ctx, 0, sizeof(ctx)); @@ -185,7 +207,9 @@ void verstage_main(void) /* Read secdata from TPM. Initialize TPM if secdata not found. We don't * check the return value here because vb2api_fw_phase1 will catch * invalid secdata and tell us what to do (=reboot). */ + timestamp_add_now(TS_START_TPMINIT); antirollback_read_space_firmware(&ctx); + timestamp_add_now(TS_END_TPMINIT); if (get_developer_mode_switch()) ctx.flags |= VB2_CONTEXT_FORCE_DEVELOPER_MODE; @@ -194,17 +218,18 @@ void verstage_main(void) ctx.flags |= VB2_CONTEXT_FORCE_RECOVERY_MODE; } - /* Do early init */ + /* Do early init (set up secdata and NVRAM, load GBB) */ printk(BIOS_INFO, "Phase 1\n"); rv = vb2api_fw_phase1(&ctx); if (rv) { printk(BIOS_INFO, "Recovery requested (%x)\n", rv); /* If we need recovery mode, leave firmware selection now */ save_if_needed(&ctx); + timestamp_add_now(TS_END_VBOOT); return; } - /* Determine which firmware slot to boot */ + /* Determine which firmware slot to boot (based on NVRAM) */ printk(BIOS_INFO, "Phase 2\n"); rv = vb2api_fw_phase2(&ctx); if (rv) { @@ -213,9 +238,11 @@ void verstage_main(void) vboot_reboot(); } - /* Try that slot */ + /* Try that slot (verify its keyblock and preamble) */ printk(BIOS_INFO, "Phase 3\n"); + timestamp_add_now(TS_START_VERIFY_SLOT); rv = vb2api_fw_phase3(&ctx); + timestamp_add_now(TS_END_VERIFY_SLOT); if (rv) { printk(BIOS_INFO, "Reboot requested (%x)\n", rv); save_if_needed(&ctx); @@ -245,6 +272,7 @@ void verstage_main(void) printk(BIOS_INFO, "Slot %c is selected\n", is_slot_a(&ctx) ? 'A' : 'B'); vb2_set_selected_region(wd, &fw_main); + timestamp_add_now(TS_END_VBOOT); } #if IS_ENABLED(CONFIG_RETURN_FROM_VERSTAGE) diff --git a/src/vendorcode/google/chromeos/vboot2/verstub.c b/src/vendorcode/google/chromeos/vboot2/verstub.c index 8f2e9b2d49..323468333c 100644 --- a/src/vendorcode/google/chromeos/vboot2/verstub.c +++ b/src/vendorcode/google/chromeos/vboot2/verstub.c @@ -21,6 +21,7 @@ #include #include #include +#include #include "../chromeos.h" #include "misc.h" #include "symbols.h" @@ -58,20 +59,22 @@ void vboot2_verify_firmware(void) wd = init_vb2_working_data(); -#if CONFIG_RETURN_FROM_VERSTAGE - /* load verstage from RO */ - entry = cbfs_load_stage(CBFS_DEFAULT_MEDIA, - CONFIG_CBFS_PREFIX "/verstage"); - if (entry == (void *)-1) - die("failed to load verstage"); + if (IS_ENABLED(CONFIG_RETURN_FROM_VERSTAGE)) { + /* load verstage from RO */ + entry = cbfs_load_stage(CBFS_DEFAULT_MEDIA, + CONFIG_CBFS_PREFIX "/verstage"); + if (entry == (void *)-1) + die("failed to load verstage"); - /* verify and select a slot */ - stage_exit(entry); -#else - verstage_main(); -#endif /* CONFIG_RETURN_FROM_VERSTAGE */ + timestamp_add_now(TS_END_COPYVER); + /* verify and select a slot */ + stage_exit(entry); + } else { + verstage_main(); + } /* jump to the selected slot */ + timestamp_add_now(TS_START_COPYROM); entry = NULL; if (vboot_is_slot_selected(wd)) { /* RW A or B */ @@ -88,6 +91,7 @@ void vboot2_verify_firmware(void) entry = cbfs_load_stage(CBFS_DEFAULT_MEDIA, CONFIG_CBFS_PREFIX "/romstage"); } + timestamp_add_now(TS_END_COPYROM); if (entry != NULL && entry != (void *)-1) stage_exit(entry); 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