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 <pgeorgi@chromium.org>
Original-Commit-Id: 7a2ce81722aba85beefcc6c81f9908422b8da8fa
Original-Change-Id: I5979bfa9445a9e0aba98ffdf8006c21096743456
Original-Signed-off-by: Julius Werner <jwerner@chromium.org>
Original-Reviewed-on: https://chromium-review.googlesource.com/234063
Original-Reviewed-by: Aaron Durbin <adurbin@chromium.org>
Reviewed-on: http://review.coreboot.org/9608
Tested-by: build bot (Jenkins)
Reviewed-by: Stefan Reinauer <stefan.reinauer@coreboot.org>

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__))

src/lib/loaders/load_and_run_romstage.c

@@ -24,6 +24,7 @@
 #include <cbfs.h>
 #include <halt.h>
 #include <program_loading.h>
+#include <timestamp.h>
 
 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);
 }

src/lib/lzma.c

@@ -12,6 +12,7 @@
 #include <console/console.h>
 #include <string.h>
 #include <lib.h>
+#include <timestamp.h>
 
 #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;
 }

src/lib/timestamp.c

@@ -25,7 +25,7 @@
 #include <arch/early_variables.h>
 #include <smp/node.h>
 
-#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;

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;
 }
 
 /**

src/vendorcode/google/chromeos/vboot2/verstage.c

@@ -21,7 +21,9 @@
 #include <arch/exception.h>
 #include <console/console.h>
 #include <console/vtxprintf.h>
+#include <delay.h>
 #include <string.h>
+#include <timestamp.h>
 #include <vb2_api.h>
 
 #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)

src/vendorcode/google/chromeos/vboot2/verstub.c

@@ -21,6 +21,7 @@
 #include <cbfs.h>
 #include <console/console.h>
 #include <string.h>
+#include <timestamp.h>
 #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
+	if (IS_ENABLED(CONFIG_RETURN_FROM_VERSTAGE)) {
-	/* load verstage from RO */
+		/* load verstage from RO */
-	entry = cbfs_load_stage(CBFS_DEFAULT_MEDIA,
+		entry = cbfs_load_stage(CBFS_DEFAULT_MEDIA,
-				CONFIG_CBFS_PREFIX "/verstage");
+					CONFIG_CBFS_PREFIX "/verstage");
-	if (entry == (void *)-1)
+		if (entry == (void *)-1)
-		die("failed to load verstage");
+			die("failed to load verstage");
 
-	/* verify and select a slot */
+		timestamp_add_now(TS_END_COPYVER);
-	stage_exit(entry);
+		/* verify and select a slot */
-#else
+		stage_exit(entry);
-	verstage_main();
+	} else {
-#endif /* CONFIG_RETURN_FROM_VERSTAGE */
+		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);

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
+ * decimal orders.
- * the value is printed.
  */
-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);
+		print_norm(v / 1000);
-		first_triple = 0;
+		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_START_COPYRAM,	"starting to load ramstage" },
-	{ TS_END_COPYRAM,	"end of copying ram stage" },
+	{ TS_END_COPYRAM,	"finished loading ramstage" },
 	{ TS_START_RAMSTAGE,	"start of ramstage" },
-	{ TS_START_BOOTBLOCK,   "start of bootblock" },
+	{ TS_START_BOOTBLOCK,	"start of bootblock" },
-	{ TS_END_BOOTBLOCK,     "end 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);
+	printf("%-50s", name);
-	print_norm(arch_convert_raw_ts_entry(stamp), 0);
+	print_norm(arch_convert_raw_ts_entry(stamp));
 	if (prev_stamp) {
 		printf(" (");
-		print_norm(arch_convert_raw_ts_entry(stamp
+		print_norm(arch_convert_raw_ts_entry(stamp - prev_stamp));
-				- prev_stamp), 0);
 		printf(")");
 	}
 	printf("\n");