lib/vboot_kernel: Log speed at which kernel was loaded

This makes it easy to spot the speed at which the eMMC controller is
running.

vb2_load_partition: read 8419 KB in 48 ms at 174342 KB/s.

The calculation looks a little funky because I wanted to perform all
multiplications before the division to avoid losing any precision.

BRANCH=grunt
BUG=b:122244718
TEST=Verified it on grunt

Change-Id: I5fac584994bc478bfb27cbd4e2ea34af0be7f1d9
Signed-off-by: Raul E Rangel <rrangel@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/platform/vboot_reference/+/1661366
Reviewed-by: Julius Werner <jwerner@chromium.org>
(cherry picked from commit 4c1a6f4872f405619f0dc4f2db477edf540fdd24)
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/platform/vboot_reference/+/1664759
diff --git a/firmware/lib/vboot_kernel.c b/firmware/lib/vboot_kernel.c
index 8d74f99..2ba0336 100644
--- a/firmware/lib/vboot_kernel.c
+++ b/firmware/lib/vboot_kernel.c
@@ -320,6 +320,7 @@
 		       uint32_t min_version,
 		       VbSharedDataKernelPart *shpart)
 {
+	uint64_t read_us = 0, start_ts;
 	struct vb2_workbuf wblocal;
 	vb2_workbuf_from_ctx(ctx, &wblocal);
 
@@ -328,12 +329,13 @@
 	if (!kbuf)
 		return VB2_ERROR_LOAD_PARTITION_WORKBUF;
 
-
+	start_ts = VbExGetTimer();
 	if (VbExStreamRead(stream, KBUF_SIZE, kbuf)) {
 		VB2_DEBUG("Unable to read start of partition.\n");
 		shpart->check_result = VBSD_LKP_CHECK_READ_START;
 		return VB2_ERROR_LOAD_PARTITION_READ_VBLOCK;
 	}
+	read_us += VbExGetTimer() - start_ts;
 
 	if (VB2_SUCCESS !=
 	    vb2_verify_kernel_vblock(ctx, kbuf, KBUF_SIZE, kernel_subkey,
@@ -388,11 +390,17 @@
 	body_readptr += body_copied;
 
 	/* Read the kernel data */
+	start_ts = VbExGetTimer();
 	if (body_toread && VbExStreamRead(stream, body_toread, body_readptr)) {
 		VB2_DEBUG("Unable to read kernel data.\n");
 		shpart->check_result = VBSD_LKP_CHECK_READ_DATA;
 		return VB2_ERROR_LOAD_PARTITION_READ_BODY;
 	}
+	read_us += VbExGetTimer() - start_ts;
+	VB2_DEBUG("read %" PRIu32 " KB in %" PRIu64 " ms at %" PRIu64 " KB/s.\n",
+		  (body_toread + KBUF_SIZE) / 1024, read_us / 1000,
+		  ((uint64_t)(body_toread + KBUF_SIZE) * 1000 * 1000) /
+			  (read_us * 1024));
 
 	/* Get key for preamble/data verification from the key block. */
 	struct vb2_public_key data_key;