[coreboot-gerrit] Patch set updated for coreboot: 710607d timestamps: You can never have enough of them!
Patrick Georgi (pgeorgi@google.com)
gerrit at coreboot.org
Mon Apr 13 21:34:02 CEST 2015
Patrick Georgi (pgeorgi at google.com) just uploaded a new patch set to gerrit, which you can find at http://review.coreboot.org/9608
-gerrit
commit 710607dab17ca80dcf409abab0350038a83d6ac7
Author: Julius Werner <jwerner at chromium.org>
Date: Tue Dec 2 20:51:19 2014 -0800
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 at chromium.org>
Original-Commit-Id: 7a2ce81722aba85beefcc6c81f9908422b8da8fa
Original-Change-Id: I5979bfa9445a9e0aba98ffdf8006c21096743456
Original-Signed-off-by: Julius Werner <jwerner at chromium.org>
Original-Reviewed-on: https://chromium-review.googlesource.com/234063
Original-Reviewed-by: Aaron Durbin <adurbin at chromium.org>
---
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 c2bc6f1..cd648ea 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 8467e90..9bd9603 100644
--- a/src/lib/loaders/load_and_run_romstage.c
+++ b/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);
}
diff --git a/src/lib/lzma.c b/src/lib/lzma.c
index 8efa1e6..89e4d97 100644
--- a/src/lib/lzma.c
+++ b/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 at 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 67635f8..5846781 100644
--- a/src/lib/timestamp.c
+++ b/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;
diff --git a/src/vendorcode/google/chromeos/vboot2/vboot_handoff.c b/src/vendorcode/google/chromeos/vboot2/vboot_handoff.c
index 7e91432..a5c7de6 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 289b93f..569e6e5 100644
--- a/src/vendorcode/google/chromeos/vboot2/verstage.c
+++ b/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)
diff --git a/src/vendorcode/google/chromeos/vboot2/verstub.c b/src/vendorcode/google/chromeos/vboot2/verstub.c
index 8f2e9b2..3234683 100644
--- a/src/vendorcode/google/chromeos/vboot2/verstub.c
+++ b/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
- /* 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 7c96c6e..0421591 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");
More information about the coreboot-gerrit
mailing list