google/brya/var/crota: selfboot jump reached after 1.2 s

Dear Google Chromebook folks,


I got a Dell Latitude 5340 Chromebook with

     coreboot-v1.9308_26_0.0.22-26491-g38c6637296

With hot MRC cache, ChromeOS login screen is reached after around six 
seconds, which is great. According to the firmware time stamps in 
`chrome://system`, coreboot takes 1.2 until starting depthcharge:

     82 entries total:

     990:CSME ROM started execution 0
     944:CSE sent 'Boot Stall Done' to PMC 119,000
     945:CSE started to handle ICC configuration 119,000 (0)
     946:CSE sent 'Host BIOS Prep Done' to PMC 123,000 (4,000)
     947:CSE received 'CPU Reset Done Ack sent' from PMC 307,000 (184,000)
     0:1st timestamp 342,717 (35,717)

So the Converged Security Engine alone takes 342 ms – as long as 
coreboot takes to execute on older systems.

     11:start of bootblock 352,538 (9,821)
     12:end of bootblock 358,690 (6,151)
     501:starting to load verstage 358,693 (3)
     502:finished loading verstage 359,785 (1,092)
     5:start of verified boot 361,037 (1,252)
     503:starting to initialize TPM 361,739 (701)
     504:finished TPM initialization 450,095 (88,356)

88 ms is high, but I think common for TPM initialization.

     505:starting to verify keyblock/preamble (RSA) 471,441 (21,345)
     506:finished verifying keyblock/preamble (RSA) 476,234 (4,793)
     507:starting to verify body (load+SHA2+RSA) 476,256 (22)
     508:finished loading body 679,079 (202,822)

Another 200 ms is spent here.

     509:finished calculating body hash (SHA2) 686,553 (7,473)
     510:finished verifying body signature (RSA) 688,054 (1,501)
     511:starting TPM PCR extend 690,511 (2,456)
     512:finished TPM PCR extend 719,107 (28,596)
     513:starting locking TPM 719,107 (0)
     514:finished locking TPM 733,290 (14,183)
     6:end of verified boot 747,454 (14,163)
     13:starting to load romstage 747,563 (108)
     14:finished loading romstage 747,575 (12)
     1:start of romstage 747,587 (12)
     515:starting EC software sync 747,596 (8)
     516:EC vboot hash ready 749,955 (2,359)
     517:waiting for EC to allow higher power draw 753,883 (3,928)
     518:finished EC software sync 755,385 (1,501)
     948:starting CSE firmware sync 756,428 (1,043)
     949:finished CSE firmware sync 759,141 (2,712)
     970:loading FSP-M 760,597 (1,456)
     2:before RAM initialization 760,603 (5)
     950:calling FspMemoryInit 785,801 (25,198)
     951:returning from FspMemoryInit 825,967 (40,165)
     550:starting to load ChromeOS VPD 826,013 (45)
     551:finished loading ChromeOS VPD (RO) 826,099 (86)
     552:finished loading ChromeOS VPD (RW) 826,132 (32)
     3:after RAM initialization 826,196 (64)
     4:end of romstage 827,576 (1,379)
     100:start of postcar 836,651 (9,074)
     101:end of postcar 836,651 (0)
     8:starting to load ramstage 836,655 (3)
     15:starting LZMA decompress (ignore for x86) 836,701 (46)
     16:finished LZMA decompress (ignore for x86) 866,740 (30,039)
     9:finished loading ramstage 866,880 (139)
     10:start of ramstage 866,929 (48)
     17:starting LZ4 decompress (ignore for x86) 867,936 (1,006)
     18:finished LZ4 decompress (ignore for x86) 907,401 (39,465)
     30:device enumeration 913,217 (5,816)
     971:loading FSP-S 923,807 (10,589)
     954:calling FspSiliconInit 934,237 (10,430)
     955:returning from FspSiliconInit 968,817 (34,579)
     962:calling FspMultiPhaseSiInit 968,822 (5)
     963:returning from FspMultiPhaseSiInit 1,146,574 (177,751)

177 ms are spent here in the FSP blob?

     942:before sending EOP to ME 1,146,823 (248)
     40:device configuration 1,149,840 (3,016)
     50:device enable 1,162,440 (12,600)
     60:device initialization 1,167,018 (4,578)
     114:started elog init 1,168,482 (1,464)
     115:finished elog init 1,170,862 (2,379)
     15:starting LZMA decompress (ignore for x86) 1,174,928 (4,065)
     16:finished LZMA decompress (ignore for x86) 1,175,208 (280)
     70:device setup done 1,186,831 (11,622)
     75:cbmem post 1,187,518 (686)
     80:write tables 1,187,593 (75)
     85:finalize chips 1,195,483 (7,889)
     553:started TPM enable update 1,204,169 (8,685)
     554:finished TPM enable update 1,223,291 (19,122)
     90:starting to load payload 1,223,317 (26)
     15:starting LZMA decompress (ignore for x86) 1,223,459 (141)
     16:finished LZMA decompress (ignore for x86) 1,236,494 (13,035)
     943:after sending EOP to ME 1,240,485 (3,990)
     99:selfboot jump 1,240,607 (122)
     1000:depthcharge start 1,248,752 (8,144)
     1002:RO vboot init 1,249,204 (452)
     1020:vboot select&load kernel 1,249,228 (23)
     1040:finished storage device initialization 1,282,580 (33,352)
     1050:finished reading kernel from disk 1,288,042 (5,461)
     1100:finished vboot kernel verification 1,295,930 (7,887)
     1101:jumping to kernel 1,314,111 (18,180)

     Total Time: 1,314,072

I thought ChromeOS requirement is to reach `selfboot jump` below (still 
quite high) one second. Or is the actually met by not counting from 
power-on but from 1st timestamp?

Does somebody know, why the CSE takes so long? Is Intel aware of that 
and going to improve that? I think there was something similar in the 
past, where Duncan Laurie(?), experienced, that coreboot was faster than 
the ME initialization, and had to wait for the Intel ME to send the 
ready signal. I think Intel improved on that later on?


Kind regards,

Paul

_______________________________________________
coreboot mailing list -- [email protected]
To unsubscribe send an email to [email protected]

TS_ME_ROM_START 0
TS_ME_BOOT_STALL_END 119000
TS_ME_ICC_CONFIG_START 0
TS_ME_HOST_BOOT_PREP_END 4000
TS_ME_RECEIVED_CRDA_FROM_PMC 184000
TS_START 35717
TS_BOOTBLOCK_START -> TS_BOOTBLOCK_END 6151
TS_COPYVER_START 3
TS_COPYVER_END 1092
TS_VBOOT_START -> TS_VBOOT_END 386416
TS_VBOOT_START -> TS_VBOOT_END;TS_TPMINIT_START -> TS_TPMINIT_END 88356
TS_VBOOT_START -> TS_VBOOT_END;TS_VERIFY_SLOT_START -> TS_VERIFY_SLOT_END 4793
TS_VBOOT_START -> TS_VBOOT_END;TS_HASH_BODY_START -> TS_HASH_BODY_END 211797
TS_VBOOT_START -> TS_VBOOT_END;TS_HASH_BODY_START -> TS_HASH_BODY_END;TS_LOADING_END 202822
TS_VBOOT_START -> TS_VBOOT_END;TS_HASH_BODY_START -> TS_HASH_BODY_END;TS_HASHING_END 7473
TS_VBOOT_START -> TS_VBOOT_END;TS_TPMPCR_START -> TS_TPMPCR_END 28596
TS_VBOOT_START -> TS_VBOOT_END;TS_TPMLOCK_START -> TS_TPMLOCK_END 14183
TS_COPYROM_START -> TS_COPYROM_END 12
TS_ROMSTAGE_START -> TS_ROMSTAGE_END 79988
TS_ROMSTAGE_START -> TS_ROMSTAGE_END;TS_EC_SYNC_START -> TS_EC_SYNC_END 7789
TS_ROMSTAGE_START -> TS_ROMSTAGE_END;TS_EC_SYNC_START -> TS_EC_SYNC_END;TS_EC_HASH_READY 2359
TS_ROMSTAGE_START -> TS_ROMSTAGE_END;TS_EC_SYNC_START -> TS_EC_SYNC_END;TS_EC_POWER_LIMIT_WAIT 3928
TS_ROMSTAGE_START -> TS_ROMSTAGE_END;TS_CSE_FW_SYNC_START -> TS_CSE_FW_SYNC_END 2712
TS_ROMSTAGE_START -> TS_ROMSTAGE_END;TS_FSP_MEMORY_INIT_LOAD 1456
TS_ROMSTAGE_START -> TS_ROMSTAGE_END;TS_INITRAM_START -> TS_INITRAM_END 65593
TS_ROMSTAGE_START -> TS_ROMSTAGE_END;TS_INITRAM_START -> TS_INITRAM_END;TS_FSP_MEMORY_INIT_START -> TS_FSP_MEMORY_INIT_END 40165
TS_ROMSTAGE_START -> TS_ROMSTAGE_END;TS_INITRAM_START -> TS_INITRAM_END;TS_COPYVPD_START -> TS_COPYVPD_RW_END 118
TS_ROMSTAGE_START -> TS_ROMSTAGE_END;TS_INITRAM_START -> TS_INITRAM_END;TS_COPYVPD_START -> TS_COPYVPD_RW_END;TS_COPYVPD_RO_END 86
TS_POSTCAR_START -> TS_POSTCAR_END 0
TS_COPYRAM_START -> TS_COPYRAM_END 30225
TS_COPYRAM_START -> TS_COPYRAM_END;TS_ULZMA_START -> TS_ULZMA_END 30039
TS_RAMSTAGE_START 48
TS_ULZ4F_START -> TS_ULZ4F_END 39465
TS_DEVICE_ENUMERATE -> TS_DEVICE_CONFIGURE 236622
TS_DEVICE_ENUMERATE -> TS_DEVICE_CONFIGURE;TS_FSP_SILICON_INIT_LOAD 10589
TS_DEVICE_ENUMERATE -> TS_DEVICE_CONFIGURE;TS_FSP_SILICON_INIT_START -> TS_FSP_SILICON_INIT_END 34579
TS_DEVICE_ENUMERATE -> TS_DEVICE_CONFIGURE;TS_FSP_MULTI_PHASE_SI_INIT_START -> TS_FSP_MULTI_PHASE_SI_INIT_END 177751
TS_DEVICE_ENUMERATE -> TS_DEVICE_CONFIGURE;TS_ME_END_OF_POST_START 248
TS_DEVICE_CONFIGURE -> TS_DEVICE_ENABLE 12600
TS_DEVICE_ENABLE -> TS_DEVICE_INITIALIZE 4578
TS_DEVICE_INITIALIZE -> TS_DEVICE_DONE 19812
TS_DEVICE_INITIALIZE -> TS_DEVICE_DONE;TS_ELOG_INIT_START -> TS_ELOG_INIT_END 2379
TS_DEVICE_INITIALIZE -> TS_DEVICE_DONE;TS_ULZMA_START -> TS_ULZMA_END 280
TS_CBMEM_POST 686
TS_WRITE_TABLES 75
TS_FINALIZE_CHIPS 7889
TS_TPM_ENABLE_UPDATE_START -> TS_TPM_ENABLE_UPDATE_END 19122
TS_LOAD_PAYLOAD 26
TS_ULZMA_START -> TS_ULZMA_END 13035
TS_ME_END_OF_POST_END 3990
TS_SELFBOOT_JUMP 122
TS_DC_START 8144
TS_RO_VB_INIT 452
TS_VB_SELECT_AND_LOAD_KERNEL 23
TS_VB_STORAGE_INIT_DONE 33352
TS_VB_READ_KERNEL_DONE 5461
TS_VB_VBOOT_DONE 7887
TS_KERNEL_START 18180