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>
This commit is contained in:
Julius Werner
Patrick Georgi
parent
b5995b5872
commit
a7d924412a
|
|
@ -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__))
|
||||
|
|
|
|||
|
|
@ -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);
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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;
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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;
|
||||
|
|
|
|||
|
|
@ -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;
|
||||
}
|
||||
|
||||
/**
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
|
|
|||
|
|
@ -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 */
|
||||
entry = cbfs_load_stage(CBFS_DEFAULT_MEDIA,
|
||||
CONFIG_CBFS_PREFIX "/verstage");
|
||||
if (entry == (void *)-1)
|
||||
die("failed to load verstage");
|
||||
|
||||
timestamp_add_now(TS_END_COPYVER);
|
||||
/* verify and select a slot */
|
||||
stage_exit(entry);
|
||||
#else
|
||||
} else {
|
||||
verstage_main();
|
||||
#endif /* CONFIG_RETURN_FROM_VERSTAGE */
|
||||
}
|
||||
|
||||
/* 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);
|
||||
|
|
|
|||
|
|
@ -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_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");
|
||||
|
|
|
|||
Loading…
Reference in New Issue