diff options
| -rw-r--r-- | src/commonlib/include/commonlib/timestamp_serialized.h | 271 | ||||
| -rw-r--r-- | util/cbmem/cbmem.c | 138 |
2 files changed, 260 insertions, 149 deletions
diff --git a/src/commonlib/include/commonlib/timestamp_serialized.h b/src/commonlib/include/commonlib/timestamp_serialized.h index 890d9882f5..63b7806e3c 100644 --- a/src/commonlib/include/commonlib/timestamp_serialized.h +++ b/src/commonlib/include/commonlib/timestamp_serialized.h @@ -166,158 +166,173 @@ enum timestamp_id { 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 { uint32_t id; + uint32_t id_end; const char *enum_name; const char *name; } timestamp_ids[] = { /* Marker to report base_time. */ - {0, "TS_START", "1st timestamp"}, - TS_NAME_DEF(TS_ROMSTAGE_START, "start of romstage"), - TS_NAME_DEF(TS_INITRAM_START, "before RAM initialization"), - TS_NAME_DEF(TS_INITRAM_END, "after RAM initialization"), - TS_NAME_DEF(TS_ROMSTAGE_END, "end of romstage"), - TS_NAME_DEF(TS_VBOOT_START, "start of verified boot"), - TS_NAME_DEF(TS_VBOOT_END, "end of verified boot"), - TS_NAME_DEF(TS_COPYRAM_START, "starting to load ramstage"), - TS_NAME_DEF(TS_COPYRAM_END, "finished loading ramstage"), - TS_NAME_DEF(TS_RAMSTAGE_START, "start of ramstage"), - TS_NAME_DEF(TS_BOOTBLOCK_START, "start of bootblock"), - TS_NAME_DEF(TS_BOOTBLOCK_END, "end of bootblock"), - TS_NAME_DEF(TS_COPYROM_START, "starting to load romstage"), - TS_NAME_DEF(TS_COPYROM_END, "finished loading romstage"), - TS_NAME_DEF(TS_ULZMA_START, "starting LZMA decompress (ignore for x86)"), - TS_NAME_DEF(TS_ULZMA_END, "finished LZMA decompress (ignore for x86)"), - TS_NAME_DEF(TS_ULZ4F_START, "starting LZ4 decompress (ignore for x86)"), - TS_NAME_DEF(TS_ULZ4F_END, "finished LZ4 decompress (ignore for x86)"), - TS_NAME_DEF(TS_DEVICE_ENUMERATE, "device enumeration"), - TS_NAME_DEF(TS_DEVICE_CONFIGURE, "device configuration"), - TS_NAME_DEF(TS_DEVICE_ENABLE, "device enable"), - TS_NAME_DEF(TS_DEVICE_INITIALIZE, "device initialization"), - TS_NAME_DEF(TS_OPROM_INITIALIZE, "Option ROM initialization"), - TS_NAME_DEF(TS_OPROM_COPY_END, "Option ROM copy done"), - TS_NAME_DEF(TS_OPROM_END, "Option ROM run done"), - TS_NAME_DEF(TS_DEVICE_DONE, "device setup done"), - TS_NAME_DEF(TS_CBMEM_POST, "cbmem post"), - TS_NAME_DEF(TS_WRITE_TABLES, "write tables"), - TS_NAME_DEF(TS_FINALIZE_CHIPS, "finalize chips"), - TS_NAME_DEF(TS_LOAD_PAYLOAD, "starting to load payload"), - TS_NAME_DEF(TS_ACPI_WAKE_JUMP, "ACPI wake jump"), - TS_NAME_DEF(TS_SELFBOOT_JUMP, "selfboot jump"), - TS_NAME_DEF(TS_POSTCAR_START, "start of postcar"), - TS_NAME_DEF(TS_POSTCAR_END, "end of postcar"), - TS_NAME_DEF(TS_DELAY_START, "Forced delay start"), - TS_NAME_DEF(TS_DELAY_END, "Forced delay end"), - TS_NAME_DEF(TS_READ_UCODE_START, "started reading uCode"), - TS_NAME_DEF(TS_READ_UCODE_END, "finished reading uCode"), - TS_NAME_DEF(TS_ELOG_INIT_START, "started elog init"), - TS_NAME_DEF(TS_ELOG_INIT_END, "finished elog init"), + {0, 0, "TS_START", "1st timestamp"}, + TS_NAME_DEF(TS_ROMSTAGE_START, TS_ROMSTAGE_END, "start of romstage"), + TS_NAME_DEF(TS_INITRAM_START, TS_INITRAM_END, "before RAM initialization"), + TS_NAME_DEF(TS_INITRAM_END, 0, "after RAM initialization"), + TS_NAME_DEF(TS_ROMSTAGE_END, 0, "end of romstage"), + TS_NAME_DEF(TS_VBOOT_START, TS_VBOOT_END, "start of verified boot"), + TS_NAME_DEF(TS_VBOOT_END, 0, "end of verified boot"), + TS_NAME_DEF(TS_COPYRAM_START, TS_COPYRAM_END, "starting to load ramstage"), + TS_NAME_DEF(TS_COPYRAM_END, 0, "finished loading ramstage"), + TS_NAME_DEF(TS_RAMSTAGE_START, 0, "start of ramstage"), + TS_NAME_DEF(TS_BOOTBLOCK_START, TS_BOOTBLOCK_END, "start of bootblock"), + TS_NAME_DEF(TS_BOOTBLOCK_END, 0, "end of bootblock"), + TS_NAME_DEF(TS_COPYROM_START, TS_COPYROM_END, "starting to load romstage"), + TS_NAME_DEF(TS_COPYROM_END, 0, "finished loading romstage"), + TS_NAME_DEF(TS_ULZMA_START, TS_ULZMA_END, "starting LZMA decompress (ignore for x86)"), + TS_NAME_DEF(TS_ULZMA_END, 0, "finished LZMA 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, 0, "finished LZ4 decompress (ignore for x86)"), + TS_NAME_DEF(TS_DEVICE_ENUMERATE, TS_DEVICE_CONFIGURE, "device enumeration"), + TS_NAME_DEF(TS_DEVICE_CONFIGURE, TS_DEVICE_ENABLE, "device configuration"), + TS_NAME_DEF(TS_DEVICE_ENABLE, TS_DEVICE_INITIALIZE, "device enable"), + TS_NAME_DEF(TS_DEVICE_INITIALIZE, TS_DEVICE_DONE, "device initialization"), + TS_NAME_DEF(TS_OPROM_INITIALIZE, TS_OPROM_END, "Option ROM initialization"), + TS_NAME_DEF(TS_OPROM_COPY_END, 0, "Option ROM copy done"), + TS_NAME_DEF(TS_OPROM_END, 0, "Option ROM run done"), + TS_NAME_DEF(TS_DEVICE_DONE, 0, "device setup done"), + TS_NAME_DEF(TS_CBMEM_POST, 0, "cbmem post"), + TS_NAME_DEF(TS_WRITE_TABLES, 0, "write tables"), + TS_NAME_DEF(TS_FINALIZE_CHIPS, 0, "finalize chips"), + TS_NAME_DEF(TS_LOAD_PAYLOAD, 0, "starting to load payload"), + TS_NAME_DEF(TS_ACPI_WAKE_JUMP, 0, "ACPI wake jump"), + TS_NAME_DEF(TS_SELFBOOT_JUMP, 0, "selfboot jump"), + TS_NAME_DEF(TS_POSTCAR_START, TS_POSTCAR_END, "start of postcar"), + TS_NAME_DEF(TS_POSTCAR_END, 0, "end of postcar"), + TS_NAME_DEF(TS_DELAY_START, TS_DELAY_END, "Forced delay start"), + TS_NAME_DEF(TS_DELAY_END, 0, "Forced delay end"), + TS_NAME_DEF(TS_READ_UCODE_START, TS_READ_UCODE_END, "started reading uCode"), + TS_NAME_DEF(TS_READ_UCODE_END, 0, "finished reading uCode"), + TS_NAME_DEF(TS_ELOG_INIT_START, TS_ELOG_INIT_END, "started elog init"), + TS_NAME_DEF(TS_ELOG_INIT_END, 0, "finished elog init"), /* Google related timestamps */ - TS_NAME_DEF(TS_COPYVER_START, "starting to load verstage"), - TS_NAME_DEF(TS_COPYVER_END, "finished loading verstage"), - TS_NAME_DEF(TS_TPMINIT_START, "starting to initialize TPM"), - TS_NAME_DEF(TS_TPMINIT_END, "finished TPM initialization"), - TS_NAME_DEF(TS_VERIFY_SLOT_START, "starting to verify keyblock/preamble (RSA)"), - TS_NAME_DEF(TS_VERIFY_SLOT_END, "finished verifying keyblock/preamble (RSA)"), - TS_NAME_DEF(TS_HASH_BODY_START, "starting to verify body (load+SHA2+RSA) "), - TS_NAME_DEF(TS_LOADING_END, "finished loading body"), - TS_NAME_DEF(TS_HASHING_END, "finished calculating body hash (SHA2)"), - TS_NAME_DEF(TS_HASH_BODY_END, "finished verifying body signature (RSA)"), - TS_NAME_DEF(TS_TPMPCR_START, "starting TPM PCR extend"), - TS_NAME_DEF(TS_TPMPCR_END, "finished TPM PCR extend"), - TS_NAME_DEF(TS_TPMLOCK_START, "starting locking TPM"), - TS_NAME_DEF(TS_TPMLOCK_END, "finished locking TPM"), - TS_NAME_DEF(TS_EC_SYNC_START, "starting EC software sync"), - TS_NAME_DEF(TS_EC_HASH_READY, "EC vboot hash ready"), - TS_NAME_DEF(TS_EC_POWER_LIMIT_WAIT, "waiting for EC to allow higher power draw"), - TS_NAME_DEF(TS_EC_SYNC_END, "finished EC software sync"), - TS_NAME_DEF(TS_COPYVPD_START, "starting to load Chrome OS VPD"), - TS_NAME_DEF(TS_COPYVPD_RO_END, "finished loading Chrome OS VPD (RO)"), - TS_NAME_DEF(TS_COPYVPD_RW_END, "finished loading Chrome OS VPD (RW)"), - TS_NAME_DEF(TS_TPM_ENABLE_UPDATE_START, "started TPM enable update"), - TS_NAME_DEF(TS_TPM_ENABLE_UPDATE_END, "finished TPM enable update"), + TS_NAME_DEF(TS_COPYVER_START, TS_COPYVER_START, "starting to load verstage"), + TS_NAME_DEF(TS_COPYVER_END, 0, "finished loading verstage"), + TS_NAME_DEF(TS_TPMINIT_START, TS_TPMINIT_END, "starting to initialize TPM"), + TS_NAME_DEF(TS_TPMINIT_END, 0, "finished TPM initialization"), + TS_NAME_DEF(TS_VERIFY_SLOT_START, TS_VERIFY_SLOT_END, + "starting to verify keyblock/preamble (RSA)"), + TS_NAME_DEF(TS_VERIFY_SLOT_END, 0, "finished verifying keyblock/preamble (RSA)"), + TS_NAME_DEF(TS_HASH_BODY_START, TS_HASH_BODY_END, + "starting to verify body (load+SHA2+RSA) "), + TS_NAME_DEF(TS_LOADING_END, 0, "finished loading body"), + TS_NAME_DEF(TS_HASHING_END, 0, "finished calculating body hash (SHA2)"), + TS_NAME_DEF(TS_HASH_BODY_END, 0, "finished verifying body signature (RSA)"), + TS_NAME_DEF(TS_TPMPCR_START, TS_TPMPCR_END, "starting TPM PCR extend"), + TS_NAME_DEF(TS_TPMPCR_END, 0, "finished TPM PCR extend"), + TS_NAME_DEF(TS_TPMLOCK_START, TS_TPMLOCK_END, "starting locking TPM"), + TS_NAME_DEF(TS_TPMLOCK_END, 0, "finished locking TPM"), + TS_NAME_DEF(TS_EC_SYNC_START, TS_EC_SYNC_END, "starting EC software sync"), + TS_NAME_DEF(TS_EC_HASH_READY, 0, "EC vboot hash ready"), + TS_NAME_DEF(TS_EC_POWER_LIMIT_WAIT, 0, "waiting for EC to allow higher power draw"), + TS_NAME_DEF(TS_EC_SYNC_END, 0, "finished EC software sync"), + TS_NAME_DEF(TS_COPYVPD_START, TS_COPYVPD_RW_END, "starting to load Chrome OS VPD"), + TS_NAME_DEF(TS_COPYVPD_RO_END, TS_COPYVPD_RW_END, + "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 */ - TS_NAME_DEF(TS_AGESA_INIT_RESET_START, "calling AmdInitReset"), - TS_NAME_DEF(TS_AGESA_INIT_RESET_END, "back from AmdInitReset"), - TS_NAME_DEF(TS_AGESA_INIT_EARLY_START, "calling AmdInitEarly"), - TS_NAME_DEF(TS_AGESA_INIT_EARLY_END, "back from AmdInitEarly"), - TS_NAME_DEF(TS_AGESA_INIT_POST_START, "calling AmdInitPost"), - TS_NAME_DEF(TS_AGESA_INIT_POST_END, "back from AmdInitPost"), - TS_NAME_DEF(TS_AGESA_INIT_ENV_START, "calling AmdInitEnv"), - TS_NAME_DEF(TS_AGESA_INIT_ENV_END, "back from AmdInitEnv"), - TS_NAME_DEF(TS_AGESA_INIT_MID_START, "calling AmdInitMid"), - TS_NAME_DEF(TS_AGESA_INIT_MID_END, "back from AmdInitMid"), - TS_NAME_DEF(TS_AGESA_INIT_LATE_START, "calling AmdInitLate"), - TS_NAME_DEF(TS_AGESA_INIT_LATE_END, "back from AmdInitLate"), - TS_NAME_DEF(TS_AGESA_INIT_RTB_START, "calling AmdInitRtb/AmdS3Save"), - TS_NAME_DEF(TS_AGESA_INIT_RTB_END, "back from AmdInitRtb/AmdS3Save"), - TS_NAME_DEF(TS_AGESA_INIT_RESUME_START, "calling AmdInitResume"), - TS_NAME_DEF(TS_AGESA_INIT_RESUME_END, "back from AmdInitResume"), - TS_NAME_DEF(TS_AGESA_S3_LATE_START, "calling AmdS3LateRestore"), - TS_NAME_DEF(TS_AGESA_S3_LATE_END, "back from AmdS3LateRestore"), - TS_NAME_DEF(TS_AGESA_S3_FINAL_START, "calling AmdS3FinalRestore"), - TS_NAME_DEF(TS_AGESA_S3_FINAL_END, "back from AmdS3FinalRestore"), - TS_NAME_DEF(TS_AMD_APOB_READ_START, "starting APOB read"), - TS_NAME_DEF(TS_AMD_APOB_ERASE_START, "starting APOB erase"), - TS_NAME_DEF(TS_AMD_APOB_WRITE_START, "starting APOB write"), - TS_NAME_DEF(TS_AMD_APOB_END, "finished APOB"), + TS_NAME_DEF(TS_AGESA_INIT_RESET_START, TS_AGESA_INIT_RESET_END, "calling AmdInitReset"), + TS_NAME_DEF(TS_AGESA_INIT_RESET_END, 0, "back from AmdInitReset"), + TS_NAME_DEF(TS_AGESA_INIT_EARLY_START, TS_AGESA_INIT_EARLY_END, "calling AmdInitEarly"), + TS_NAME_DEF(TS_AGESA_INIT_EARLY_END, 0, "back from AmdInitEarly"), + TS_NAME_DEF(TS_AGESA_INIT_POST_START, TS_AGESA_INIT_POST_END, "calling AmdInitPost"), + TS_NAME_DEF(TS_AGESA_INIT_POST_END, 0, "back from AmdInitPost"), + TS_NAME_DEF(TS_AGESA_INIT_ENV_START, TS_AGESA_INIT_ENV_END, "calling AmdInitEnv"), + TS_NAME_DEF(TS_AGESA_INIT_ENV_END, 0, "back from AmdInitEnv"), + TS_NAME_DEF(TS_AGESA_INIT_MID_START, TS_AGESA_INIT_MID_END, "calling AmdInitMid"), + TS_NAME_DEF(TS_AGESA_INIT_MID_END, 0, "back from AmdInitMid"), + TS_NAME_DEF(TS_AGESA_INIT_LATE_START, TS_AGESA_INIT_LATE_END, "calling AmdInitLate"), + TS_NAME_DEF(TS_AGESA_INIT_LATE_END, 0, "back from AmdInitLate"), + TS_NAME_DEF(TS_AGESA_INIT_RTB_START, TS_AGESA_INIT_RTB_END, + "calling AmdInitRtb/AmdS3Save"), + TS_NAME_DEF(TS_AGESA_INIT_RTB_END, 0, "back from AmdInitRtb/AmdS3Save"), + TS_NAME_DEF(TS_AGESA_INIT_RESUME_START, TS_AGESA_INIT_RESUME_END, + "calling AmdInitResume"), + TS_NAME_DEF(TS_AGESA_INIT_RESUME_END, 0, "back from AmdInitResume"), + TS_NAME_DEF(TS_AGESA_S3_LATE_START, TS_AGESA_S3_LATE_END, "calling AmdS3LateRestore"), + TS_NAME_DEF(TS_AGESA_S3_LATE_END, 0, "back from AmdS3LateRestore"), + TS_NAME_DEF(TS_AGESA_S3_FINAL_START, TS_AGESA_S3_FINAL_END, + "calling AmdS3FinalRestore"), + TS_NAME_DEF(TS_AGESA_S3_FINAL_END, 0, "back from AmdS3FinalRestore"), + 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 */ - TS_NAME_DEF(TS_ME_INFORM_DRAM_START, "waiting for ME acknowledgement of raminit"), - TS_NAME_DEF(TS_ME_INFORM_DRAM_END, "finished waiting for ME response"), - TS_NAME_DEF(TS_ME_END_OF_POST_START, "before sending EOP to ME"), - TS_NAME_DEF(TS_ME_END_OF_POST_END, "after sending EOP to ME"), - TS_NAME_DEF(TS_ME_BOOT_STALL_END, "CSE sent 'Boot Stall Done' to PMC"), - TS_NAME_DEF(TS_ME_ICC_CONFIG_START, "CSE started to handle ICC configuration"), - TS_NAME_DEF(TS_ME_HOST_BOOT_PREP_END, "CSE sent 'Host BIOS Prep Done' to PMC"), - TS_NAME_DEF(TS_ME_RECEIVED_CRDA_FROM_PMC, + TS_NAME_DEF(TS_ME_INFORM_DRAM_START, TS_ME_INFORM_DRAM_END, + "waiting for ME acknowledgement of raminit"), + TS_NAME_DEF(TS_ME_INFORM_DRAM_END, 0, "finished waiting for ME response"), + 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_END_OF_POST_END, 0, "after sending EOP to ME"), + TS_NAME_DEF(TS_ME_BOOT_STALL_END, 0, "CSE sent 'Boot Stall Done' to PMC"), + TS_NAME_DEF(TS_ME_ICC_CONFIG_START, 0, "CSE started to handle ICC configuration"), + 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"), - TS_NAME_DEF(TS_CSE_FW_SYNC_START, "starting CSE firmware sync"), - TS_NAME_DEF(TS_CSE_FW_SYNC_END, "finished 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, 0, "finished CSE firmware sync"), /* FSP related timestamps */ - TS_NAME_DEF(TS_FSP_MEMORY_INIT_START, "calling FspMemoryInit"), - TS_NAME_DEF(TS_FSP_MEMORY_INIT_END, "returning from FspMemoryInit"), - TS_NAME_DEF(TS_FSP_TEMP_RAM_EXIT_START, "calling FspTempRamExit"), - TS_NAME_DEF(TS_FSP_TEMP_RAM_EXIT_END, "returning from FspTempRamExit"), - TS_NAME_DEF(TS_FSP_SILICON_INIT_START, "calling FspSiliconInit"), - TS_NAME_DEF(TS_FSP_SILICON_INIT_END, "returning from FspSiliconInit"), - TS_NAME_DEF(TS_FSP_MULTI_PHASE_SI_INIT_START, "calling FspMultiPhaseSiInit"), - TS_NAME_DEF(TS_FSP_MULTI_PHASE_SI_INIT_END, "returning from FspMultiPhaseSiInit"), - TS_NAME_DEF(TS_FSP_ENUMERATE_START, "calling FspNotify(AfterPciEnumeration)"), - TS_NAME_DEF(TS_FSP_ENUMERATE_END, "returning from FspNotify(AfterPciEnumeration)"), - TS_NAME_DEF(TS_FSP_FINALIZE_START, "calling FspNotify(ReadyToBoot)"), - TS_NAME_DEF(TS_FSP_FINALIZE_END, "returning from FspNotify(ReadyToBoot)"), - TS_NAME_DEF(TS_FSP_END_OF_FIRMWARE_START, "calling FspNotify(EndOfFirmware)"), - TS_NAME_DEF(TS_FSP_END_OF_FIRMWARE_END, "returning from FspNotify(EndOfFirmware)"), - TS_NAME_DEF(TS_FSP_MEMORY_INIT_LOAD, "loading FSP-M"), - TS_NAME_DEF(TS_FSP_SILICON_INIT_LOAD, "loading FSP-S"), + TS_NAME_DEF(TS_FSP_MEMORY_INIT_START, TS_FSP_MEMORY_INIT_END, "calling FspMemoryInit"), + TS_NAME_DEF(TS_FSP_MEMORY_INIT_END, 0, "returning from FspMemoryInit"), + TS_NAME_DEF(TS_FSP_TEMP_RAM_EXIT_START, TS_FSP_TEMP_RAM_EXIT_END, + "calling FspTempRamExit"), + TS_NAME_DEF(TS_FSP_TEMP_RAM_EXIT_END, 0, "returning from FspTempRamExit"), + TS_NAME_DEF(TS_FSP_SILICON_INIT_START, TS_FSP_SILICON_INIT_END, + "calling FspSiliconInit"), + TS_NAME_DEF(TS_FSP_SILICON_INIT_END, 0, "returning from FspSiliconInit"), + TS_NAME_DEF(TS_FSP_MULTI_PHASE_SI_INIT_START, TS_FSP_MULTI_PHASE_SI_INIT_END, + "calling FspMultiPhaseSiInit"), + TS_NAME_DEF(TS_FSP_MULTI_PHASE_SI_INIT_END, 0, "returning from FspMultiPhaseSiInit"), + TS_NAME_DEF(TS_FSP_ENUMERATE_START, TS_FSP_ENUMERATE_END, + "calling FspNotify(AfterPciEnumeration)"), + TS_NAME_DEF(TS_FSP_ENUMERATE_END, 0, "returning from FspNotify(AfterPciEnumeration)"), + TS_NAME_DEF(TS_FSP_FINALIZE_START, TS_FSP_FINALIZE_END, + "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 */ - 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 */ - 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_VB_INIT, "RO vboot init"), - TS_NAME_DEF(TS_RO_VB_SELECT_FIRMWARE, "RO vboot select firmware"), - TS_NAME_DEF(TS_RO_VB_SELECT_AND_LOAD_KERNEL, "RO vboot select&load kernel"), + TS_NAME_DEF(TS_RO_PARAMS_INIT, 0, "RO parameter init"), + TS_NAME_DEF(TS_RO_VB_INIT, 0, "RO vboot init"), + TS_NAME_DEF(TS_RO_VB_SELECT_FIRMWARE, 0, "RO vboot select firmware"), + 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_EC_VBOOT_DONE, "finished EC verification"), - TS_NAME_DEF(TS_VB_STORAGE_INIT_DONE, "finished storage device initialization"), - TS_NAME_DEF(TS_VB_READ_KERNEL_DONE, "finished reading kernel from disk"), - TS_NAME_DEF(TS_VB_VBOOT_DONE, "finished vboot kernel verification"), + TS_NAME_DEF(TS_VB_SELECT_AND_LOAD_KERNEL, 0, "vboot select&load kernel"), + TS_NAME_DEF(TS_VB_EC_VBOOT_DONE, 0, "finished EC verification"), + TS_NAME_DEF(TS_VB_STORAGE_INIT_DONE, 0, "finished storage device initialization"), + TS_NAME_DEF(TS_VB_READ_KERNEL_DONE, 0, "finished reading kernel from disk"), + 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_DECOMPRESSION, "starting kernel decompression/relocation"), + TS_NAME_DEF(TS_KERNEL_START, 0, "jumping to kernel"), + TS_NAME_DEF(TS_KERNEL_DECOMPRESSION, 0, "starting kernel decompression/relocation"), }; #endif diff --git a/util/cbmem/cbmem.c b/util/cbmem/cbmem.c index 0fd69d6e06..5b969e4b8b 100644 --- a/util/cbmem/cbmem.c +++ b/util/cbmem/cbmem.c @@ -1,6 +1,7 @@ /* SPDX-License-Identifier: GPL-2.0-only */ #include <inttypes.h> +#include <stdbool.h> #include <stdio.h> #include <stdlib.h> #include <string.h> @@ -590,14 +591,72 @@ static int compare_timestamp_entries(const void *a, const void *b) 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 */ -static void dump_timestamps(int mach_readable) +static void dump_timestamps(enum timestamps_print_type output_type) { const struct timestamp_table *tst_p; struct timestamp_table *sorted_tst_p; size_t size; - uint64_t prev_stamp; - uint64_t total_time; + uint64_t prev_stamp = 0; + uint64_t total_time = 0; struct mapping timestamp_mapping; 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); - if (!mach_readable) + if (output_type == TIMESTAMPS_PRINT_NORMAL) printf("%d entries total:\n\n", tst_p->num_entries); 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; } - 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++) { uint64_t stamp; const struct timestamp_entry *tse = &sorted_tst_p->entries[i]; /* Make all timestamps absolute. */ stamp = tse->entry_stamp + sorted_tst_p->base_time; - if (mach_readable) - total_time += - timestamp_print_parseable_entry(tse->entry_id, - stamp, prev_stamp); - else - total_time += timestamp_print_entry(tse->entry_id, - stamp, prev_stamp); + if (output_type == TIMESTAMPS_PRINT_MACHINE_READABLE) { + timestamp_print_parseable_entry(tse->entry_id, stamp, prev_stamp); + } else if (output_type == TIMESTAMPS_PRINT_NORMAL) { + total_time += timestamp_print_entry(tse->entry_id, stamp, prev_stamp); + } else if (output_type == TIMESTAMPS_PRINT_STACKED) { + bool end_of_range = false; + /* 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; } - if (!mach_readable) { + if (output_type == TIMESTAMPS_PRINT_NORMAL) { printf("\nTotal Time: "); print_norm(total_time); 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" " -t | --timestamps: print timestamp information\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" " -V | --verbose: verbose (debugging) output\n" " -v | --version: print the version\n" @@ -1301,9 +1391,8 @@ int main(int argc, char** argv) int print_list = 0; int print_hexdump = 0; int print_rawdump = 0; - int print_timestamps = 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; unsigned int rawdump_id = 0; int max_loglevel = BIOS_NEVER; @@ -1320,6 +1409,7 @@ int main(int argc, char** argv) {"tcpa-log", 0, 0, 'L'}, {"timestamps", 0, 0, 't'}, {"parseable-timestamps", 0, 0, 'T'}, + {"stacked-timestamps", 0, 0, 'S'}, {"hexdump", 0, 0, 'x'}, {"rawdump", required_argument, 0, 'r'}, {"verbose", 0, 0, 'V'}, @@ -1327,7 +1417,7 @@ int main(int argc, char** argv) {"help", 0, 0, 'h'}, {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) { switch (opt) { case 'c': @@ -1369,12 +1459,15 @@ int main(int argc, char** argv) rawdump_id = strtoul(optarg, NULL, 16); break; case 't': - print_timestamps = 1; + timestamp_type = TIMESTAMPS_PRINT_NORMAL; print_defaults = 0; break; case 'T': - print_timestamps = 1; - machine_readable_timestamps = 1; + timestamp_type = TIMESTAMPS_PRINT_MACHINE_READABLE; + print_defaults = 0; + break; + case 'S': + timestamp_type = TIMESTAMPS_PRINT_STACKED; print_defaults = 0; break; case 'V': @@ -1486,8 +1579,11 @@ int main(int argc, char** argv) if (print_rawdump) dump_cbmem_raw(rawdump_id); - if (print_defaults || print_timestamps) - dump_timestamps(machine_readable_timestamps); + if (print_defaults) + timestamp_type = TIMESTAMPS_PRINT_NORMAL; + + if (timestamp_type != TIMESTAMPS_PRINT_NONE) + dump_timestamps(timestamp_type); if (print_tcpa_log) dump_tcpa_log(); |