GNUBoot
/
coreboot-kgpe-d16
2
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

util/cbmem: Add FlameGraph-compatible timestamps output 

Flame graphs are used to visualize hierarchical data, like call stacks.
Timestamps collected by coreboot can be processed to resemble
profiler-like output, and thus can be feed to flame graph generation
tools.

Generating flame graph using https://github.com/brendangregg/FlameGraph:
  cbmem -S > trace.txt
  FlameGraph/flamegraph.pl --flamechart trace.txt > output.svg

TEST=Run on coreboot-enabled device and extract timestamps using
     -t/-T/-S options

Signed-off-by: Jakub Czapiga <jacz@semihalf.com>
Change-Id: I3a4e20a267e9e0fbc6b3a4d6a2409b32ce8fca33
Reviewed-on: https://review.coreboot.org/c/coreboot/+/62474
Tested-by: build bot (Jenkins) <no-reply@coreboot.org>
Reviewed-by: Julius Werner <jwerner@chromium.org>
This commit is contained in:
Jakub Czapiga 2022-02-28 16:23:02 +01:00 committed by Julius Werner
parent f91366fa6f
commit 48f6c2b46f
2 changed files with 260 additions and 149 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

271
src/commonlib/include/commonlib/timestamp_serialized.h
View File

@ -166,158 +166,173 @@ enum timestamp_id {
TS_KERNEL_DECOMPRESSION = 1102, TS_KERNEL_DECOMPRESSION = 1102,
}; };
#define TS_NAME_DEF(id, desc) {(id), STRINGIFY(id), (desc)} #define TS_NAME_DEF(id, id_end, desc) {(id), (id_end), STRINGIFY(id), (desc)}
static const struct timestamp_id_to_name { static const struct timestamp_id_to_name {
uint32_t id; uint32_t id;
uint32_t id_end;
const char *enum_name; const char *enum_name;
const char *name; const char *name;
} timestamp_ids[] = { } timestamp_ids[] = {
/* Marker to report base_time. */ /* Marker to report base_time. */
{0, "TS_START", "1st timestamp"}, {0, 0, "TS_START", "1st timestamp"},
TS_NAME_DEF(TS_ROMSTAGE_START, "start of romstage"), TS_NAME_DEF(TS_ROMSTAGE_START, TS_ROMSTAGE_END, "start of romstage"),
TS_NAME_DEF(TS_INITRAM_START, "before RAM initialization"), TS_NAME_DEF(TS_INITRAM_START, TS_INITRAM_END, "before RAM initialization"),
TS_NAME_DEF(TS_INITRAM_END, "after RAM initialization"), TS_NAME_DEF(TS_INITRAM_END, 0, "after RAM initialization"),
TS_NAME_DEF(TS_ROMSTAGE_END, "end of romstage"), TS_NAME_DEF(TS_ROMSTAGE_END, 0, "end of romstage"),
TS_NAME_DEF(TS_VBOOT_START, "start of verified boot"), TS_NAME_DEF(TS_VBOOT_START, TS_VBOOT_END, "start of verified boot"),
TS_NAME_DEF(TS_VBOOT_END, "end of verified boot"), TS_NAME_DEF(TS_VBOOT_END, 0, "end of verified boot"),
TS_NAME_DEF(TS_COPYRAM_START, "starting to load ramstage"), TS_NAME_DEF(TS_COPYRAM_START, TS_COPYRAM_END, "starting to load ramstage"),
TS_NAME_DEF(TS_COPYRAM_END, "finished loading ramstage"), TS_NAME_DEF(TS_COPYRAM_END, 0, "finished loading ramstage"),
TS_NAME_DEF(TS_RAMSTAGE_START, "start of ramstage"), TS_NAME_DEF(TS_RAMSTAGE_START, 0, "start of ramstage"),
TS_NAME_DEF(TS_BOOTBLOCK_START, "start of bootblock"), TS_NAME_DEF(TS_BOOTBLOCK_START, TS_BOOTBLOCK_END, "start of bootblock"),
TS_NAME_DEF(TS_BOOTBLOCK_END, "end of bootblock"), TS_NAME_DEF(TS_BOOTBLOCK_END, 0, "end of bootblock"),
TS_NAME_DEF(TS_COPYROM_START, "starting to load romstage"), TS_NAME_DEF(TS_COPYROM_START, TS_COPYROM_END, "starting to load romstage"),
TS_NAME_DEF(TS_COPYROM_END, "finished loading romstage"), TS_NAME_DEF(TS_COPYROM_END, 0, "finished loading romstage"),
TS_NAME_DEF(TS_ULZMA_START, "starting LZMA decompress (ignore for x86)"), TS_NAME_DEF(TS_ULZMA_START, TS_ULZMA_END, "starting LZMA decompress (ignore for x86)"),
TS_NAME_DEF(TS_ULZMA_END, "finished LZMA decompress (ignore for x86)"), TS_NAME_DEF(TS_ULZMA_END, 0, "finished LZMA decompress (ignore for x86)"),
TS_NAME_DEF(TS_ULZ4F_START, "starting LZ4 decompress (ignore for x86)"), TS_NAME_DEF(TS_ULZ4F_START, TS_ULZ4F_END, "starting LZ4 decompress (ignore for x86)"),
TS_NAME_DEF(TS_ULZ4F_END, "finished LZ4 decompress (ignore for x86)"), TS_NAME_DEF(TS_ULZ4F_END, 0, "finished LZ4 decompress (ignore for x86)"),
TS_NAME_DEF(TS_DEVICE_ENUMERATE, "device enumeration"), TS_NAME_DEF(TS_DEVICE_ENUMERATE, TS_DEVICE_CONFIGURE, "device enumeration"),
TS_NAME_DEF(TS_DEVICE_CONFIGURE, "device configuration"), TS_NAME_DEF(TS_DEVICE_CONFIGURE, TS_DEVICE_ENABLE, "device configuration"),
TS_NAME_DEF(TS_DEVICE_ENABLE, "device enable"), TS_NAME_DEF(TS_DEVICE_ENABLE, TS_DEVICE_INITIALIZE, "device enable"),
TS_NAME_DEF(TS_DEVICE_INITIALIZE, "device initialization"), TS_NAME_DEF(TS_DEVICE_INITIALIZE, TS_DEVICE_DONE, "device initialization"),
TS_NAME_DEF(TS_OPROM_INITIALIZE, "Option ROM initialization"), TS_NAME_DEF(TS_OPROM_INITIALIZE, TS_OPROM_END, "Option ROM initialization"),
TS_NAME_DEF(TS_OPROM_COPY_END, "Option ROM copy done"), TS_NAME_DEF(TS_OPROM_COPY_END, 0, "Option ROM copy done"),
TS_NAME_DEF(TS_OPROM_END, "Option ROM run done"), TS_NAME_DEF(TS_OPROM_END, 0, "Option ROM run done"),
TS_NAME_DEF(TS_DEVICE_DONE, "device setup done"), TS_NAME_DEF(TS_DEVICE_DONE, 0, "device setup done"),
TS_NAME_DEF(TS_CBMEM_POST, "cbmem post"), TS_NAME_DEF(TS_CBMEM_POST, 0, "cbmem post"),
TS_NAME_DEF(TS_WRITE_TABLES, "write tables"), TS_NAME_DEF(TS_WRITE_TABLES, 0, "write tables"),
TS_NAME_DEF(TS_FINALIZE_CHIPS, "finalize chips"), TS_NAME_DEF(TS_FINALIZE_CHIPS, 0, "finalize chips"),
TS_NAME_DEF(TS_LOAD_PAYLOAD, "starting to load payload"), TS_NAME_DEF(TS_LOAD_PAYLOAD, 0, "starting to load payload"),
TS_NAME_DEF(TS_ACPI_WAKE_JUMP, "ACPI wake jump"), TS_NAME_DEF(TS_ACPI_WAKE_JUMP, 0, "ACPI wake jump"),
TS_NAME_DEF(TS_SELFBOOT_JUMP, "selfboot jump"), TS_NAME_DEF(TS_SELFBOOT_JUMP, 0, "selfboot jump"),
TS_NAME_DEF(TS_POSTCAR_START, "start of postcar"), TS_NAME_DEF(TS_POSTCAR_START, TS_POSTCAR_END, "start of postcar"),
TS_NAME_DEF(TS_POSTCAR_END, "end of postcar"), TS_NAME_DEF(TS_POSTCAR_END, 0, "end of postcar"),
TS_NAME_DEF(TS_DELAY_START, "Forced delay start"), TS_NAME_DEF(TS_DELAY_START, TS_DELAY_END, "Forced delay start"),
TS_NAME_DEF(TS_DELAY_END, "Forced delay end"), TS_NAME_DEF(TS_DELAY_END, 0, "Forced delay end"),
TS_NAME_DEF(TS_READ_UCODE_START, "started reading uCode"), TS_NAME_DEF(TS_READ_UCODE_START, TS_READ_UCODE_END, "started reading uCode"),
TS_NAME_DEF(TS_READ_UCODE_END, "finished reading uCode"), TS_NAME_DEF(TS_READ_UCODE_END, 0, "finished reading uCode"),
TS_NAME_DEF(TS_ELOG_INIT_START, "started elog init"), TS_NAME_DEF(TS_ELOG_INIT_START, TS_ELOG_INIT_END, "started elog init"),
TS_NAME_DEF(TS_ELOG_INIT_END, "finished elog init"), TS_NAME_DEF(TS_ELOG_INIT_END, 0, "finished elog init"),
/* Google related timestamps */ /* Google related timestamps */
TS_NAME_DEF(TS_COPYVER_START, "starting to load verstage"), TS_NAME_DEF(TS_COPYVER_START, TS_COPYVER_START, "starting to load verstage"),
TS_NAME_DEF(TS_COPYVER_END, "finished loading verstage"), TS_NAME_DEF(TS_COPYVER_END, 0, "finished loading verstage"),
TS_NAME_DEF(TS_TPMINIT_START, "starting to initialize TPM"), TS_NAME_DEF(TS_TPMINIT_START, TS_TPMINIT_END, "starting to initialize TPM"),
TS_NAME_DEF(TS_TPMINIT_END, "finished TPM initialization"), TS_NAME_DEF(TS_TPMINIT_END, 0, "finished TPM initialization"),
TS_NAME_DEF(TS_VERIFY_SLOT_START, "starting to verify keyblock/preamble (RSA)"), TS_NAME_DEF(TS_VERIFY_SLOT_START, TS_VERIFY_SLOT_END,
TS_NAME_DEF(TS_VERIFY_SLOT_END, "finished verifying keyblock/preamble (RSA)"), "starting to verify keyblock/preamble (RSA)"),
TS_NAME_DEF(TS_HASH_BODY_START, "starting to verify body (load+SHA2+RSA) "), TS_NAME_DEF(TS_VERIFY_SLOT_END, 0, "finished verifying keyblock/preamble (RSA)"),
TS_NAME_DEF(TS_LOADING_END, "finished loading body"), TS_NAME_DEF(TS_HASH_BODY_START, TS_HASH_BODY_END,
TS_NAME_DEF(TS_HASHING_END, "finished calculating body hash (SHA2)"), "starting to verify body (load+SHA2+RSA) "),
TS_NAME_DEF(TS_HASH_BODY_END, "finished verifying body signature (RSA)"), TS_NAME_DEF(TS_LOADING_END, 0, "finished loading body"),
TS_NAME_DEF(TS_TPMPCR_START, "starting TPM PCR extend"), TS_NAME_DEF(TS_HASHING_END, 0, "finished calculating body hash (SHA2)"),
TS_NAME_DEF(TS_TPMPCR_END, "finished TPM PCR extend"), TS_NAME_DEF(TS_HASH_BODY_END, 0, "finished verifying body signature (RSA)"),
TS_NAME_DEF(TS_TPMLOCK_START, "starting locking TPM"), TS_NAME_DEF(TS_TPMPCR_START, TS_TPMPCR_END, "starting TPM PCR extend"),
TS_NAME_DEF(TS_TPMLOCK_END, "finished locking TPM"), TS_NAME_DEF(TS_TPMPCR_END, 0, "finished TPM PCR extend"),
TS_NAME_DEF(TS_EC_SYNC_START, "starting EC software sync"), TS_NAME_DEF(TS_TPMLOCK_START, TS_TPMLOCK_END, "starting locking TPM"),
TS_NAME_DEF(TS_EC_HASH_READY, "EC vboot hash ready"), TS_NAME_DEF(TS_TPMLOCK_END, 0, "finished locking TPM"),
TS_NAME_DEF(TS_EC_POWER_LIMIT_WAIT, "waiting for EC to allow higher power draw"), TS_NAME_DEF(TS_EC_SYNC_START, TS_EC_SYNC_END, "starting EC software sync"),
TS_NAME_DEF(TS_EC_SYNC_END, "finished EC software sync"), TS_NAME_DEF(TS_EC_HASH_READY, 0, "EC vboot hash ready"),
TS_NAME_DEF(TS_COPYVPD_START, "starting to load Chrome OS VPD"), TS_NAME_DEF(TS_EC_POWER_LIMIT_WAIT, 0, "waiting for EC to allow higher power draw"),
TS_NAME_DEF(TS_COPYVPD_RO_END, "finished loading Chrome OS VPD (RO)"), TS_NAME_DEF(TS_EC_SYNC_END, 0, "finished EC software sync"),
TS_NAME_DEF(TS_COPYVPD_RW_END, "finished loading Chrome OS VPD (RW)"), TS_NAME_DEF(TS_COPYVPD_START, TS_COPYVPD_RW_END, "starting to load Chrome OS VPD"),
TS_NAME_DEF(TS_TPM_ENABLE_UPDATE_START, "started TPM enable update"), TS_NAME_DEF(TS_COPYVPD_RO_END, TS_COPYVPD_RW_END,
TS_NAME_DEF(TS_TPM_ENABLE_UPDATE_END, "finished TPM enable update"), "finished loading Chrome OS VPD (RO)"),
TS_NAME_DEF(TS_COPYVPD_RW_END, 0, "finished loading Chrome OS VPD (RW)"),
TS_NAME_DEF(TS_TPM_ENABLE_UPDATE_START, TS_TPM_ENABLE_UPDATE_END,
"started TPM enable update"),
TS_NAME_DEF(TS_TPM_ENABLE_UPDATE_END, 0, "finished TPM enable update"),
/* AMD related timestamps */ /* AMD related timestamps */
TS_NAME_DEF(TS_AGESA_INIT_RESET_START, "calling AmdInitReset"), TS_NAME_DEF(TS_AGESA_INIT_RESET_START, TS_AGESA_INIT_RESET_END, "calling AmdInitReset"),
TS_NAME_DEF(TS_AGESA_INIT_RESET_END, "back from AmdInitReset"), TS_NAME_DEF(TS_AGESA_INIT_RESET_END, 0, "back from AmdInitReset"),
TS_NAME_DEF(TS_AGESA_INIT_EARLY_START, "calling AmdInitEarly"), TS_NAME_DEF(TS_AGESA_INIT_EARLY_START, TS_AGESA_INIT_EARLY_END, "calling AmdInitEarly"),
TS_NAME_DEF(TS_AGESA_INIT_EARLY_END, "back from AmdInitEarly"), TS_NAME_DEF(TS_AGESA_INIT_EARLY_END, 0, "back from AmdInitEarly"),
TS_NAME_DEF(TS_AGESA_INIT_POST_START, "calling AmdInitPost"), TS_NAME_DEF(TS_AGESA_INIT_POST_START, TS_AGESA_INIT_POST_END, "calling AmdInitPost"),
TS_NAME_DEF(TS_AGESA_INIT_POST_END, "back from AmdInitPost"), TS_NAME_DEF(TS_AGESA_INIT_POST_END, 0, "back from AmdInitPost"),
TS_NAME_DEF(TS_AGESA_INIT_ENV_START, "calling AmdInitEnv"), TS_NAME_DEF(TS_AGESA_INIT_ENV_START, TS_AGESA_INIT_ENV_END, "calling AmdInitEnv"),
TS_NAME_DEF(TS_AGESA_INIT_ENV_END, "back from AmdInitEnv"), TS_NAME_DEF(TS_AGESA_INIT_ENV_END, 0, "back from AmdInitEnv"),
TS_NAME_DEF(TS_AGESA_INIT_MID_START, "calling AmdInitMid"), TS_NAME_DEF(TS_AGESA_INIT_MID_START, TS_AGESA_INIT_MID_END, "calling AmdInitMid"),
TS_NAME_DEF(TS_AGESA_INIT_MID_END, "back from AmdInitMid"), TS_NAME_DEF(TS_AGESA_INIT_MID_END, 0, "back from AmdInitMid"),
TS_NAME_DEF(TS_AGESA_INIT_LATE_START, "calling AmdInitLate"), TS_NAME_DEF(TS_AGESA_INIT_LATE_START, TS_AGESA_INIT_LATE_END, "calling AmdInitLate"),
TS_NAME_DEF(TS_AGESA_INIT_LATE_END, "back from AmdInitLate"), TS_NAME_DEF(TS_AGESA_INIT_LATE_END, 0, "back from AmdInitLate"),
TS_NAME_DEF(TS_AGESA_INIT_RTB_START, "calling AmdInitRtb/AmdS3Save"), TS_NAME_DEF(TS_AGESA_INIT_RTB_START, TS_AGESA_INIT_RTB_END,
TS_NAME_DEF(TS_AGESA_INIT_RTB_END, "back from AmdInitRtb/AmdS3Save"), "calling AmdInitRtb/AmdS3Save"),
TS_NAME_DEF(TS_AGESA_INIT_RESUME_START, "calling AmdInitResume"), TS_NAME_DEF(TS_AGESA_INIT_RTB_END, 0, "back from AmdInitRtb/AmdS3Save"),
TS_NAME_DEF(TS_AGESA_INIT_RESUME_END, "back from AmdInitResume"), TS_NAME_DEF(TS_AGESA_INIT_RESUME_START, TS_AGESA_INIT_RESUME_END,
TS_NAME_DEF(TS_AGESA_S3_LATE_START, "calling AmdS3LateRestore"), "calling AmdInitResume"),
TS_NAME_DEF(TS_AGESA_S3_LATE_END, "back from AmdS3LateRestore"), TS_NAME_DEF(TS_AGESA_INIT_RESUME_END, 0, "back from AmdInitResume"),
TS_NAME_DEF(TS_AGESA_S3_FINAL_START, "calling AmdS3FinalRestore"), TS_NAME_DEF(TS_AGESA_S3_LATE_START, TS_AGESA_S3_LATE_END, "calling AmdS3LateRestore"),
TS_NAME_DEF(TS_AGESA_S3_FINAL_END, "back from AmdS3FinalRestore"), TS_NAME_DEF(TS_AGESA_S3_LATE_END, 0, "back from AmdS3LateRestore"),
TS_NAME_DEF(TS_AMD_APOB_READ_START, "starting APOB read"), TS_NAME_DEF(TS_AGESA_S3_FINAL_START, TS_AGESA_S3_FINAL_END,
TS_NAME_DEF(TS_AMD_APOB_ERASE_START, "starting APOB erase"), "calling AmdS3FinalRestore"),
TS_NAME_DEF(TS_AMD_APOB_WRITE_START, "starting APOB write"), TS_NAME_DEF(TS_AGESA_S3_FINAL_END, 0, "back from AmdS3FinalRestore"),
TS_NAME_DEF(TS_AMD_APOB_END, "finished APOB"), TS_NAME_DEF(TS_AMD_APOB_READ_START, TS_AMD_APOB_END, "starting APOB read"),
TS_NAME_DEF(TS_AMD_APOB_ERASE_START, TS_AMD_APOB_WRITE_START, "starting APOB erase"),
TS_NAME_DEF(TS_AMD_APOB_WRITE_START, TS_AMD_APOB_END, "starting APOB write"),
TS_NAME_DEF(TS_AMD_APOB_END, 0, "finished APOB"),
/* Intel ME related timestamps */ /* Intel ME related timestamps */
TS_NAME_DEF(TS_ME_INFORM_DRAM_START, "waiting for ME acknowledgement of raminit"), TS_NAME_DEF(TS_ME_INFORM_DRAM_START, TS_ME_INFORM_DRAM_END,
TS_NAME_DEF(TS_ME_INFORM_DRAM_END, "finished waiting for ME response"), "waiting for ME acknowledgement of raminit"),
TS_NAME_DEF(TS_ME_END_OF_POST_START, "before sending EOP to ME"), TS_NAME_DEF(TS_ME_INFORM_DRAM_END, 0, "finished waiting for ME response"),
TS_NAME_DEF(TS_ME_END_OF_POST_END, "after sending EOP to ME"), TS_NAME_DEF(TS_ME_END_OF_POST_START, TS_ME_END_OF_POST_END, "before sending EOP to ME"),
TS_NAME_DEF(TS_ME_BOOT_STALL_END, "CSE sent 'Boot Stall Done' to PMC"), TS_NAME_DEF(TS_ME_END_OF_POST_END, 0, "after sending EOP to ME"),
TS_NAME_DEF(TS_ME_ICC_CONFIG_START, "CSE started to handle ICC configuration"), TS_NAME_DEF(TS_ME_BOOT_STALL_END, 0, "CSE sent 'Boot Stall Done' to PMC"),
TS_NAME_DEF(TS_ME_HOST_BOOT_PREP_END, "CSE sent 'Host BIOS Prep Done' to PMC"), TS_NAME_DEF(TS_ME_ICC_CONFIG_START, 0, "CSE started to handle ICC configuration"),
TS_NAME_DEF(TS_ME_RECEIVED_CRDA_FROM_PMC, TS_NAME_DEF(TS_ME_HOST_BOOT_PREP_END, 0, "CSE sent 'Host BIOS Prep Done' to PMC"),
TS_NAME_DEF(TS_ME_RECEIVED_CRDA_FROM_PMC, 0,
"CSE received 'CPU Reset Done Ack sent' from PMC"), "CSE received 'CPU Reset Done Ack sent' from PMC"),
TS_NAME_DEF(TS_CSE_FW_SYNC_START, "starting CSE firmware sync"), TS_NAME_DEF(TS_CSE_FW_SYNC_START, TS_CSE_FW_SYNC_END, "starting CSE firmware sync"),
TS_NAME_DEF(TS_CSE_FW_SYNC_END, "finished CSE firmware sync"), TS_NAME_DEF(TS_CSE_FW_SYNC_END, 0, "finished CSE firmware sync"),
/* FSP related timestamps */ /* FSP related timestamps */
TS_NAME_DEF(TS_FSP_MEMORY_INIT_START, "calling FspMemoryInit"), TS_NAME_DEF(TS_FSP_MEMORY_INIT_START, TS_FSP_MEMORY_INIT_END, "calling FspMemoryInit"),
TS_NAME_DEF(TS_FSP_MEMORY_INIT_END, "returning from FspMemoryInit"), TS_NAME_DEF(TS_FSP_MEMORY_INIT_END, 0, "returning from FspMemoryInit"),
TS_NAME_DEF(TS_FSP_TEMP_RAM_EXIT_START, "calling FspTempRamExit"), TS_NAME_DEF(TS_FSP_TEMP_RAM_EXIT_START, TS_FSP_TEMP_RAM_EXIT_END,
TS_NAME_DEF(TS_FSP_TEMP_RAM_EXIT_END, "returning from FspTempRamExit"), "calling FspTempRamExit"),
TS_NAME_DEF(TS_FSP_SILICON_INIT_START, "calling FspSiliconInit"), TS_NAME_DEF(TS_FSP_TEMP_RAM_EXIT_END, 0, "returning from FspTempRamExit"),
TS_NAME_DEF(TS_FSP_SILICON_INIT_END, "returning from FspSiliconInit"), TS_NAME_DEF(TS_FSP_SILICON_INIT_START, TS_FSP_SILICON_INIT_END,
TS_NAME_DEF(TS_FSP_MULTI_PHASE_SI_INIT_START, "calling FspMultiPhaseSiInit"), "calling FspSiliconInit"),
TS_NAME_DEF(TS_FSP_MULTI_PHASE_SI_INIT_END, "returning from FspMultiPhaseSiInit"), TS_NAME_DEF(TS_FSP_SILICON_INIT_END, 0, "returning from FspSiliconInit"),
TS_NAME_DEF(TS_FSP_ENUMERATE_START, "calling FspNotify(AfterPciEnumeration)"), TS_NAME_DEF(TS_FSP_MULTI_PHASE_SI_INIT_START, TS_FSP_MULTI_PHASE_SI_INIT_END,
TS_NAME_DEF(TS_FSP_ENUMERATE_END, "returning from FspNotify(AfterPciEnumeration)"), "calling FspMultiPhaseSiInit"),
TS_NAME_DEF(TS_FSP_FINALIZE_START, "calling FspNotify(ReadyToBoot)"), TS_NAME_DEF(TS_FSP_MULTI_PHASE_SI_INIT_END, 0, "returning from FspMultiPhaseSiInit"),
TS_NAME_DEF(TS_FSP_FINALIZE_END, "returning from FspNotify(ReadyToBoot)"), TS_NAME_DEF(TS_FSP_ENUMERATE_START, TS_FSP_ENUMERATE_END,
TS_NAME_DEF(TS_FSP_END_OF_FIRMWARE_START, "calling FspNotify(EndOfFirmware)"), "calling FspNotify(AfterPciEnumeration)"),
TS_NAME_DEF(TS_FSP_END_OF_FIRMWARE_END, "returning from FspNotify(EndOfFirmware)"), TS_NAME_DEF(TS_FSP_ENUMERATE_END, 0, "returning from FspNotify(AfterPciEnumeration)"),
TS_NAME_DEF(TS_FSP_MEMORY_INIT_LOAD, "loading FSP-M"), TS_NAME_DEF(TS_FSP_FINALIZE_START, TS_FSP_FINALIZE_END,
TS_NAME_DEF(TS_FSP_SILICON_INIT_LOAD, "loading FSP-S"), "calling FspNotify(ReadyToBoot)"),
TS_NAME_DEF(TS_FSP_FINALIZE_END, 0, "returning from FspNotify(ReadyToBoot)"),
TS_NAME_DEF(TS_FSP_END_OF_FIRMWARE_START, TS_FSP_END_OF_FIRMWARE_END,
"calling FspNotify(EndOfFirmware)"),
TS_NAME_DEF(TS_FSP_END_OF_FIRMWARE_END, 0, "returning from FspNotify(EndOfFirmware)"),
TS_NAME_DEF(TS_FSP_MEMORY_INIT_LOAD, 0, "loading FSP-M"),
TS_NAME_DEF(TS_FSP_SILICON_INIT_LOAD, 0, "loading FSP-S"),
/* Intel ME continued */ /* Intel ME continued */
TS_NAME_DEF(TS_ME_ROM_START, "CSME ROM started execution"), TS_NAME_DEF(TS_ME_ROM_START, 0, "CSME ROM started execution"),
/* Depthcharge entry timestamp */ /* Depthcharge entry timestamp */
TS_NAME_DEF(TS_DC_START, "depthcharge start"), TS_NAME_DEF(TS_DC_START, 0, "depthcharge start"),
TS_NAME_DEF(TS_RO_PARAMS_INIT, "RO parameter init"), TS_NAME_DEF(TS_RO_PARAMS_INIT, 0, "RO parameter init"),
TS_NAME_DEF(TS_RO_VB_INIT, "RO vboot init"), TS_NAME_DEF(TS_RO_VB_INIT, 0, "RO vboot init"),
TS_NAME_DEF(TS_RO_VB_SELECT_FIRMWARE, "RO vboot select firmware"), TS_NAME_DEF(TS_RO_VB_SELECT_FIRMWARE, 0, "RO vboot select firmware"),
TS_NAME_DEF(TS_RO_VB_SELECT_AND_LOAD_KERNEL, "RO vboot select&load kernel"), TS_NAME_DEF(TS_RO_VB_SELECT_AND_LOAD_KERNEL, 0, "RO vboot select&load kernel"),
TS_NAME_DEF(TS_RW_VB_SELECT_AND_LOAD_KERNEL, "RW vboot select&load kernel"), TS_NAME_DEF(TS_RW_VB_SELECT_AND_LOAD_KERNEL, 0, "RW vboot select&load kernel"),
TS_NAME_DEF(TS_VB_SELECT_AND_LOAD_KERNEL, "vboot select&load kernel"), TS_NAME_DEF(TS_VB_SELECT_AND_LOAD_KERNEL, 0, "vboot select&load kernel"),
TS_NAME_DEF(TS_VB_EC_VBOOT_DONE, "finished EC verification"), TS_NAME_DEF(TS_VB_EC_VBOOT_DONE, 0, "finished EC verification"),
TS_NAME_DEF(TS_VB_STORAGE_INIT_DONE, "finished storage device initialization"), TS_NAME_DEF(TS_VB_STORAGE_INIT_DONE, 0, "finished storage device initialization"),
TS_NAME_DEF(TS_VB_READ_KERNEL_DONE, "finished reading kernel from disk"), TS_NAME_DEF(TS_VB_READ_KERNEL_DONE, 0, "finished reading kernel from disk"),
TS_NAME_DEF(TS_VB_VBOOT_DONE, "finished vboot kernel verification"), TS_NAME_DEF(TS_VB_VBOOT_DONE, 0, "finished vboot kernel verification"),
TS_NAME_DEF(TS_KERNEL_START, "jumping to kernel"), TS_NAME_DEF(TS_KERNEL_START, 0, "jumping to kernel"),
TS_NAME_DEF(TS_KERNEL_DECOMPRESSION, "starting kernel decompression/relocation"), TS_NAME_DEF(TS_KERNEL_DECOMPRESSION, 0, "starting kernel decompression/relocation"),
}; };
#endif #endif

138
util/cbmem/cbmem.c
View File

@ -1,6 +1,7 @@
/* SPDX-License-Identifier: GPL-2.0-only */ /* SPDX-License-Identifier: GPL-2.0-only */
#include <inttypes.h> #include <inttypes.h>
#include <stdbool.h>
#include <stdio.h> #include <stdio.h>
#include <stdlib.h> #include <stdlib.h>
#include <string.h> #include <string.h>
@ -590,14 +591,72 @@ static int compare_timestamp_entries(const void *a, const void *b)
return 0; return 0;
} }
static int find_matching_end(struct timestamp_table *sorted_tst_p, uint32_t start, uint32_t end)
{
uint32_t id = sorted_tst_p->entries[start].entry_id;
uint32_t possible_match = 0;
for (uint32_t i = 0; i < ARRAY_SIZE(timestamp_ids); ++i) {
if (timestamp_ids[i].id == id) {
possible_match = timestamp_ids[i].id_end;
break;
}
}
/* No match found or timestamp not defined in IDs table */
if (!possible_match)
return -1;
for (uint32_t i = start + 1; i < end; i++)
if (sorted_tst_p->entries[i].entry_id == possible_match)
return i;
return -1;
}
static const char *get_timestamp_name(const uint32_t id)
{
for (uint32_t i = 0; i < ARRAY_SIZE(timestamp_ids); i++)
if (timestamp_ids[i].id == id)
return timestamp_ids[i].enum_name;
return "UNKNOWN";
}
struct ts_range_stack {
const char *name;
const char *end_name;
uint32_t end;
};
static void print_with_path(struct ts_range_stack *range_stack, const int stacklvl,
const uint64_t stamp, const char *last_part)
{
for (int i = 1; i <= stacklvl; ++i) {
printf("%s -> %s", range_stack[i].name, range_stack[i].end_name);
if (i < stacklvl || last_part)
putchar(';');
}
if (last_part)
printf("%s", last_part);
printf(" %lu\n", arch_convert_raw_ts_entry(stamp));
}
enum timestamps_print_type {
TIMESTAMPS_PRINT_NONE,
TIMESTAMPS_PRINT_NORMAL,
TIMESTAMPS_PRINT_MACHINE_READABLE,
TIMESTAMPS_PRINT_STACKED,
};
/* dump the timestamp table */ /* dump the timestamp table */
static void dump_timestamps(int mach_readable) static void dump_timestamps(enum timestamps_print_type output_type)
{ {
const struct timestamp_table *tst_p; const struct timestamp_table *tst_p;
struct timestamp_table *sorted_tst_p; struct timestamp_table *sorted_tst_p;
size_t size; size_t size;
uint64_t prev_stamp; uint64_t prev_stamp = 0;
uint64_t total_time; uint64_t total_time = 0;
struct mapping timestamp_mapping; struct mapping timestamp_mapping;
if (timestamps.tag != LB_TAG_TIMESTAMPS) { if (timestamps.tag != LB_TAG_TIMESTAMPS) {
@ -612,7 +671,7 @@ static void dump_timestamps(int mach_readable)
timestamp_set_tick_freq(tst_p->tick_freq_mhz); timestamp_set_tick_freq(tst_p->tick_freq_mhz);
if (!mach_readable) if (output_type == TIMESTAMPS_PRINT_NORMAL)
printf("%d entries total:\n\n", tst_p->num_entries); printf("%d entries total:\n\n", tst_p->num_entries);
size += tst_p->num_entries * sizeof(tst_p->entries[0]); size += tst_p->num_entries * sizeof(tst_p->entries[0]);
@ -649,24 +708,54 @@ static void dump_timestamps(int mach_readable)
prev_stamp = tst_p->base_time; prev_stamp = tst_p->base_time;
} }
total_time = 0; struct ts_range_stack range_stack[20];
range_stack[0].end = sorted_tst_p->num_entries;
int stacklvl = 0;
for (uint32_t i = 0; i < sorted_tst_p->num_entries; i++) { for (uint32_t i = 0; i < sorted_tst_p->num_entries; i++) {
uint64_t stamp; uint64_t stamp;
const struct timestamp_entry *tse = &sorted_tst_p->entries[i]; const struct timestamp_entry *tse = &sorted_tst_p->entries[i];
/* Make all timestamps absolute. */ /* Make all timestamps absolute. */
stamp = tse->entry_stamp + sorted_tst_p->base_time; stamp = tse->entry_stamp + sorted_tst_p->base_time;
if (mach_readable) if (output_type == TIMESTAMPS_PRINT_MACHINE_READABLE) {
total_time += timestamp_print_parseable_entry(tse->entry_id, stamp, prev_stamp);
timestamp_print_parseable_entry(tse->entry_id, } else if (output_type == TIMESTAMPS_PRINT_NORMAL) {
stamp, prev_stamp); total_time += timestamp_print_entry(tse->entry_id, stamp, prev_stamp);
else } else if (output_type == TIMESTAMPS_PRINT_STACKED) {
total_time += timestamp_print_entry(tse->entry_id, bool end_of_range = false;
stamp, prev_stamp); /* Iterate over stacked entries to pop all ranges, which are closed by
current element. For example, assuming two ranges: (TS_A, TS_C),
(TS_B, TS_C) it will pop all of them instead of just last one. */
while (stacklvl > 0 && range_stack[stacklvl].end == i) {
end_of_range = true;
stacklvl--;
}
int match =
find_matching_end(sorted_tst_p, i, range_stack[stacklvl].end);
if (match != -1) {
const uint64_t match_stamp =
sorted_tst_p->entries[match].entry_stamp
+ sorted_tst_p->base_time;
stacklvl++;
assert(stacklvl < (int)ARRAY_SIZE(range_stack));
range_stack[stacklvl].name = get_timestamp_name(tse->entry_id);
range_stack[stacklvl].end_name = get_timestamp_name(
sorted_tst_p->entries[match].entry_id);
range_stack[stacklvl].end = match;
print_with_path(range_stack, stacklvl, match_stamp - stamp,
NULL);
} else if (!end_of_range) {
print_with_path(range_stack, stacklvl, stamp - prev_stamp,
get_timestamp_name(tse->entry_id));
}
/* else: No match && end_of_range == true */
}
prev_stamp = stamp; prev_stamp = stamp;
} }
if (!mach_readable) { if (output_type == TIMESTAMPS_PRINT_NORMAL) {
printf("\nTotal Time: "); printf("\nTotal Time: ");
print_norm(total_time); print_norm(total_time);
printf("\n"); printf("\n");
@ -1170,6 +1259,7 @@ static void print_usage(const char *name, int exit_code)
" -r | --rawdump ID: print rawdump of specific ID (in hex) of cbtable\n" " -r | --rawdump ID: print rawdump of specific ID (in hex) of cbtable\n"
" -t | --timestamps: print timestamp information\n" " -t | --timestamps: print timestamp information\n"
" -T | --parseable-timestamps: print parseable timestamps\n" " -T | --parseable-timestamps: print parseable timestamps\n"
" -S | --stacked-timestamps: print stacked timestamps (e.g. for flame graph tools)\n"
" -L | --tcpa-log print TCPA log\n" " -L | --tcpa-log print TCPA log\n"
" -V | --verbose: verbose (debugging) output\n" " -V | --verbose: verbose (debugging) output\n"
" -v | --version: print the version\n" " -v | --version: print the version\n"
@ -1301,9 +1391,8 @@ int main(int argc, char** argv)
int print_list = 0; int print_list = 0;
int print_hexdump = 0; int print_hexdump = 0;
int print_rawdump = 0; int print_rawdump = 0;
int print_timestamps = 0;
int print_tcpa_log = 0; int print_tcpa_log = 0;
int machine_readable_timestamps = 0; enum timestamps_print_type timestamp_type = TIMESTAMPS_PRINT_NONE;
enum console_print_type console_type = CONSOLE_PRINT_FULL; enum console_print_type console_type = CONSOLE_PRINT_FULL;
unsigned int rawdump_id = 0; unsigned int rawdump_id = 0;
int max_loglevel = BIOS_NEVER; int max_loglevel = BIOS_NEVER;
@ -1320,6 +1409,7 @@ int main(int argc, char** argv)
{"tcpa-log", 0, 0, 'L'}, {"tcpa-log", 0, 0, 'L'},
{"timestamps", 0, 0, 't'}, {"timestamps", 0, 0, 't'},
{"parseable-timestamps", 0, 0, 'T'}, {"parseable-timestamps", 0, 0, 'T'},
{"stacked-timestamps", 0, 0, 'S'},
{"hexdump", 0, 0, 'x'}, {"hexdump", 0, 0, 'x'},
{"rawdump", required_argument, 0, 'r'}, {"rawdump", required_argument, 0, 'r'},
{"verbose", 0, 0, 'V'}, {"verbose", 0, 0, 'V'},
@ -1327,7 +1417,7 @@ int main(int argc, char** argv)
{"help", 0, 0, 'h'}, {"help", 0, 0, 'h'},
{0, 0, 0, 0} {0, 0, 0, 0}
}; };
while ((opt = getopt_long(argc, argv, "c12B:CltTLxVvh?r:", while ((opt = getopt_long(argc, argv, "c12B:CltTSLxVvh?r:",
long_options, &option_index)) != EOF) { long_options, &option_index)) != EOF) {
switch (opt) { switch (opt) {
case 'c': case 'c':
@ -1369,12 +1459,15 @@ int main(int argc, char** argv)
rawdump_id = strtoul(optarg, NULL, 16); rawdump_id = strtoul(optarg, NULL, 16);
break; break;
case 't': case 't':
print_timestamps = 1; timestamp_type = TIMESTAMPS_PRINT_NORMAL;
print_defaults = 0; print_defaults = 0;
break; break;
case 'T': case 'T':
print_timestamps = 1; timestamp_type = TIMESTAMPS_PRINT_MACHINE_READABLE;
machine_readable_timestamps = 1; print_defaults = 0;
break;
case 'S':
timestamp_type = TIMESTAMPS_PRINT_STACKED;
print_defaults = 0; print_defaults = 0;
break; break;
case 'V': case 'V':
@ -1486,8 +1579,11 @@ int main(int argc, char** argv)
if (print_rawdump) if (print_rawdump)
dump_cbmem_raw(rawdump_id); dump_cbmem_raw(rawdump_id);
if (print_defaults || print_timestamps) if (print_defaults)
dump_timestamps(machine_readable_timestamps); timestamp_type = TIMESTAMPS_PRINT_NORMAL;
if (timestamp_type != TIMESTAMPS_PRINT_NONE)
dump_timestamps(timestamp_type);
if (print_tcpa_log) if (print_tcpa_log)
dump_tcpa_log(); dump_tcpa_log();