security/vboot/sync_ec: Add timestamps

Add 4 new timestamps to the EC software sync flow:
1) Beginning of EC software sync
2) EC finished calculating Vboot hash
3) EC is no longer requesting power limiting
4) End of EC software sync

BUG=none
BRANCH=none
TEST=verified timestamps show up in cbmem log

Change-Id: I6e5703c146b5ec27d01700fdb39cb3d2092ea8a8
Signed-off-by: Tim Wawrzynczak <twawrzynczak@chromium.org>
Reviewed-on: https://review.coreboot.org/c/coreboot/+/36209
Tested-by: build bot (Jenkins) <no-reply@coreboot.org>
Reviewed-by: Julius Werner <jwerner@chromium.org>

2 files changed, 22 insertions, 6 deletions

diff --git a/src/commonlib/include/commonlib/timestamp_serialized.h b/src/commonlib/include/commonlib/timestamp_serialized.h
index 7b1a7301c7..d7d636e6a4 100644
--- a/src/commonlib/include/commonlib/timestamp_serialized.h
+++ b/src/commonlib/include/commonlib/timestamp_serialized.h
@@ -79,6 +79,10 @@ enum timestamp_id {
 	TS_END_TPMPCR = 512,
 	TS_START_TPMLOCK = 513,
 	TS_END_TPMLOCK = 514,
+	TS_START_EC_SYNC = 515,
+	TS_EC_HASH_READY = 516,
+	TS_EC_POWER_LIMIT_WAIT = 517,
+	TS_END_EC_SYNC = 518,
 	TS_START_COPYVPD = 550,
 	TS_END_COPYVPD_RO = 551,
 	TS_END_COPYVPD_RW = 552,
@@ -202,6 +206,11 @@ static const struct timestamp_id_to_name {
 	{ TS_END_COPYVPD_RO,	"finished loading Chrome OS VPD (RO)" },
 	{ TS_END_COPYVPD_RW,	"finished loading Chrome OS VPD (RW)" },
 
+	{ TS_START_EC_SYNC,	"starting EC software sync" },
+	{ TS_EC_HASH_READY,	"EC vboot hash ready" },
+	{ TS_EC_POWER_LIMIT_WAIT,	"waiting for EC to allow higher power draw" },
+	{ TS_END_EC_SYNC,	"finished EC software sync" },
+
 	{ TS_DC_START,		"depthcharge start" },
 	{ TS_RO_PARAMS_INIT,	"RO parameter init" },
 	{ TS_RO_VB_INIT,	"RO vboot init" },
diff --git a/src/security/vboot/ec_sync.c b/src/security/vboot/ec_sync.c
index ec048aa91c..c2a6b25f90 100644
--- a/src/security/vboot/ec_sync.c
+++ b/src/security/vboot/ec_sync.c
@@ -20,6 +20,7 @@
 #include <security/vboot/vbnv.h>
 #include <security/vboot/vboot_common.h>
 #include <timer.h>
+#include <timestamp.h>
 #include <vb2_api.h>
 
 #define _EC_FILENAME(select, suffix) \
@@ -51,6 +52,8 @@ void vboot_sync_ec(void)
 	vb2_error_t retval = VB2_SUCCESS;
 	struct vb2_context *ctx;
 
+	timestamp_add_now(TS_START_EC_SYNC);
+
 	ctx = vboot_get_context();
 	ctx->flags |= VB2_CONTEXT_EC_SYNC_SUPPORTED;
 
@@ -61,6 +64,8 @@ void vboot_sync_ec(void)
 		printk(BIOS_ERR, "EC software sync failed (%#x), rebooting\n", retval);
 		vboot_reboot();
 	}
+
+	timestamp_add_now(TS_END_EC_SYNC);
 }
 
 /* Convert firmware image type into a flash offset */
@@ -138,6 +143,8 @@ static vb2_error_t ec_hash_image(enum vb2_firmware_selection select,
 	} while (resp.status == EC_VBOOT_HASH_STATUS_BUSY &&
 		 !stopwatch_expired(&sw));
 
+	timestamp_add_now(TS_EC_HASH_READY);
+
 	if (resp.status != EC_VBOOT_HASH_STATUS_DONE) {
 		printk(BIOS_ERR, "%s: Hash status not done: %d\n", __func__,
 		       resp.status);
@@ -415,7 +422,6 @@ vb2_error_t vb2ex_ec_vboot_done(struct vb2_context *ctx)
 	int limit_power = 0;
 	bool message_printed = false;
 	struct stopwatch sw;
-	vb2_error_t rv = VB2_SUCCESS;
 	int in_recovery = !!(ctx->flags & VB2_CONTEXT_RECOVERY_MODE);
 
 	/*
@@ -425,15 +431,16 @@ vb2_error_t vb2ex_ec_vboot_done(struct vb2_context *ctx)
 	if (in_recovery)
 		return VB2_SUCCESS;
 
+	timestamp_add_now(TS_EC_POWER_LIMIT_WAIT);
+
 	stopwatch_init_msecs_expire(&sw, LIMIT_POWER_WAIT_TIMEOUT_MS);
 
-	/* Ensure we have enough power to continue booting */
+	/* Ensure we have enough power to continue booting. */
 	while (1) {
 		if (google_chromeec_read_limit_power_request(&limit_power)) {
 			printk(BIOS_ERR, "Failed to check EC limit power"
 			       "flag.\n");
-			rv = VB2_ERROR_UNKNOWN;
-			break;
+			return VB2_ERROR_UNKNOWN;
 		}
 
 		if (!limit_power || stopwatch_expired(&sw))
@@ -451,13 +458,13 @@ vb2_error_t vb2ex_ec_vboot_done(struct vb2_context *ctx)
 	if (limit_power) {
 		printk(BIOS_INFO,
 		       "EC requests limited power usage. Request shutdown.\n");
-		rv = VBERROR_SHUTDOWN_REQUESTED;
+		return VBERROR_SHUTDOWN_REQUESTED;
 	} else {
 		printk(BIOS_INFO, "Waited %luus to clear limit power flag.\n",
 			stopwatch_duration_usecs(&sw));
 	}
 
-	return rv;
+	return VB2_SUCCESS;
 }
 
 /*