Boot time profiling - Githubissues

jhand2 commented 1 year ago

We should do profiling of how long Caliptra boot takes and collect metrics on which part(s) of boot take the longest. This will help identify areas for optimization to lessen Caliptra's impact on overall SoC boot time.

flanfly commented 1 year ago

Do you imagine this profiling to be done on the actual hardware or on the simulator? I'm asking because I'm trying to understand how much data is going to be collected. I presume the hardware does not have enough memory to store whole traces but only a few timestamps.

jhand2 commented 1 year ago

We don't have real hardware, so it would need to be with verilator (or FPGA) probably. I think we can measure cycle count to figure out how fast it will be on real hardware.

jlmahowa-amd commented 1 year ago

Attached log from FPGA. A couple things to keep in mind:

Current FPGA logging mechanism introduces delays as the FW waits for the test to acknowledge each byte.
Integration spec suggests a clock of 400MHz. Current FPGA is at 20MHz.

fpga_log_July19.txt

andreslagarcavilla commented 1 year ago

Adding @benjamindoron @ArthurHeymans @nquarton @ericeilertson @attzonko

As discussed, can we

fork the boot smoke test into one using an invalid LMS key that will consume the most time
characterize boot timing cycles for "normal" and worst case scenarios

Benjamin and Arthur, can you help Nick and Alex from AMD and Eric from Microsoft, land this?

I'm not sure who to assign ownership to within this group. Thanks

nquarton commented 1 year ago

Here are the full logs for the boot with LMS enabled for both the valid key and an invalid key. The timing isn’t all that different, but the invalid key is a bit slower as expected.

This is just the smoke test with minor modifications:

Turned on LMS verify (this will be committed in a PR soon)
Logging around the LMS verify calls and image verify in general to get the timing data
The invalid LMS case was modified to ignore the LMS verify failure and continue to boot.

Invalid LMS key full log

      6,155 ready_for_fuses is high
      6,329 writing to cptra_bootfsm_go
test smoke_test has been running for over 60 seconds
    195,166 UART: 
    195,209 UART: Running Caliptra ROM ...
    196,318 UART: 
    196,881 UART: [state] CFI Enabled
    198,267 UART: [state] LifecycleState = Production
    199,931 UART: [state] DebugLocked = Yes
    202,189 UART: [state] Starting the Watchdog Timer
    346,030 UART: ROM Digest: ABD791D9580684A694D2C76F8FD092C362B3A10888D1186EF51B89750A7346D3
    356,595 UART: [kat] ++
    357,023 UART: [kat] sha1
    366,191 UART: [kat] SHA2-256
    368,970 UART: [kat] SHA2-384
    373,031 UART: [kat] SHA2-384-ACC
    375,146 UART: [kat] ECC-384
  3,943,214 UART: [kat] HMAC-384
  3,953,021 UART: [kat] LMS
  5,009,096 UART: [kat] --
  5,012,051 UART: [cold-reset] ++
  5,014,013 UART: [idev] ++
  5,014,465 UART: [idev] CDI.KEYID = 6
  5,015,445 UART: [idev] SUBJECT.KEYID = 7
  5,016,585 UART: [idev] UDS.KEYID = 0
  5,034,986 UART: [idev] Erasing UDS.KEYID = 0
  8,297,173 UART: [idev] Using Sha1 for KeyId Algorithm
  8,319,582 UART: [idev] --
  8,323,451 UART: [ldev] ++
  8,323,917 UART: [ldev] CDI.KEYID = 6
  8,324,887 UART: [ldev] SUBJECT.KEYID = 5
  8,326,041 UART: [ldev] AUTHORITY.KEYID = 7
  8,327,293 UART: [ldev] FE.KEYID = 1
  8,338,135 UART: [ldev] Erasing FE.KEYID = 1
 11,617,678 UART: [ldev] Signing Cert with AUTHORITY.KEYID = 7
 15,210,901 UART: [ldev] PUB.X = 842C00AF05ACCCEB14514E2D37B0C3AAA218F15057F1DCB824A214980B744688A0888A0297FA7DC5E1EAD8CA1291DB22
 15,225,744 UART: [ldev] PUB.Y = 9C28EB8678BCE800822C07228F416AE49D218E5DA2F2D1A8A27DC19ADF668A74628999D222B40159D8076FAFBB8C5EDB
 15,240,942 UART: [ldev] SIG.R = 0C1B95861ADA0DF572438E88B23DDD5B2C24C974DF359988CC54E39E3145635A94E3D8196B49164CAD991714C2B18892
 15,255,768 UART: [ldev] SIG.S = 4BEDF2A7DEC9405964ADF4949819FADE2CD785CD0307078F74EA4E5CDDF8D1FAE5380507AB09871344CA288FA6961532
 15,276,081 UART: [ldev] --
 15,283,901 UART: [state] Stopping the Watchdog Timer
 15,287,093 ready_for_fw is high
 15,287,095 <<< Executing mbox cmd 0x46574c44 (53148 bytes) from SoC
 15,287,135 UART: [afmc] Waiting for Commands...
 15,313,888 UART: [afmc] Received Image of size 53148 bytes
 15,316,455 UART: [state] Starting the Watchdog Timer
 15,377,669 UART:                 ---Verify start---
 16,678,302 UART: LMS verify start
 16,679,033 UART: 
 18,822,987 UART: LMS verify complete
 18,823,847 UART: 
 20,115,541 UART: LMS verify start
 20,116,272 UART: 
 22,122,872 UART: LMS verify complete
 22,123,732 UART: 
 22,165,436 UART:                 ---Verify complete---
 22,166,490 UART: [afmc] Image verified using Vendor ECC Key Index 0
 22,320,063 UART: [afmc] Loading FMC at address 0x40000000 len 12672
 22,398,936 UART: [afmc] Loading Runtime at address 0x40004000 len 34592
 22,611,323 >>> mbox cmd response: success
 22,614,805 UART: [afmc] ++
 22,615,257 UART: [afmc] CDI.KEYID = 6
 22,616,237 UART: [afmc] SUBJECT.KEYID = 7
 22,617,391 UART: [afmc] AUTHORITY.KEYID = 5
 25,916,519 UART: [afmc] Signing Cert with AUTHORITY.KEYID = 5
 28,208,577 UART: [afmc] Erasing AUTHORITY.KEYID = 5
 29,517,037 UART: [afmc] PUB.X = 6C12037B7CB703F6B6351E2B58B8C0F74CCA034AB2B32A0F3DFAACB7F4AEE71C92FD200B9139CA9374613BF17916E016
 29,531,914 UART: [afmc] PUB.Y = 2ECF032A99B32BAF5833DB3FB55E2BA3A95E194AA89F2E3062914A96DD4DCC36C4624915475A64ADB5D8BA633BCAC665
 29,547,130 UART: [afmc] SIG.R = C70CCF27E49E9F5C84D7F54A6CB2017370211B3A31AD5D6F82DD681EF3AE4F03A0EAFF90B61A936076D399D2F2E14173
 29,561,987 UART: [afmc] SIG.S = 175F7EF43468584D266EE299FD6E14AC743532E973AF98F265BDE622BD0CEB2124CE0A9D4F1753197DEA890A8C64E529
 29,586,466 UART: [afmc] --
 29,590,695 UART: [cold-reset] --
 29,599,643 UART: [fht] Storing FHT @ 0x50003000
 29,604,268 UART: [state] Stopping the Watchdog Timer
 29,607,992 UART: [state] Locking Datavault
 29,611,556 UART: [state] Locking PCR0 and PCR1
 29,612,870 UART: [state] Locking ICCM
 29,615,474 UART: [exit] Launching FMC @ 0x40000134
 29,623,813 UART: 
 29,623,843 UART: Running Caliptra FMC ...
 29,624,600 UART: 
 29,625,488 UART: [alias rt] Extend RT PCRs
 29,686,050 UART: [alias rt] Extend RT PCRs Done
 29,686,986 UART: [alias rt] Lock RT PCRs
 29,687,716 UART: [alias rt] Lock RT PCRs Done
 29,688,592 UART: [alias rt] Populate DV
 29,689,400 UART: [alias rt] Populate DV Done
 29,690,297 UART: Handoff : FMC CDI: 6
 29,690,966 UART: FMC Alias Private Key: 7
 29,692,777 UART: [alias rt] Derive CDI
 29,693,444 UART: [alias rt] Store in in slot 0x4
 29,726,993 UART: [alias rt] Derive Key Pair
 29,727,810 UART: [alias rt] Store priv key in slot 0x5
 32,966,376 UART: [alias rt] Derive Key Pair - Done
 32,977,313 UART: [alias rt] Signing Cert with AUTHO
 32,978,363 UART:             RITY.KEYID = 7
 35,256,189 UART: [alias rt] Erasing AUTHORITY.KEYID = 7
 35,257,570 UART: [alias rt] PUB.X = 32A6D582B583918C96CA2400CD3423DBD51076BA8CFA5EEF72FD4D46F74FA246634B2222CBE7A094738BFA7CB322F0A0
 35,264,571 UART: [alias rt] PUB.Y = AB6C0512DB4AC6B76BDEE3757187768E2AD1B50FA4DB4449ADED0CEB2FF9E5931D8D461C11C75517DC1E56A22730A42D
 35,271,760 UART: [alias rt] SIG.R = 63596F136CE52E8BE069DA868B0DFB512C5233AC63D9C4C1A3EAAD8955A37EAC67E1A919A31B8A9E0405592561A6CF3E
 35,278,760 UART: [alias rt] SIG.S = 0ED431FFEEA71AFB7CF01571A0F144FA767F08E4D9F131EB1266282B6659ACA9F269C77164B8B7D11BA8875638C63605
 36,579,939 UART: 
 36,579,969 UART:   ____      _ _       _               ____ _____
 36,581,439 UART:  / ___|__ _| (_)_ __ | |_ _ __ __ _  |  _ \_   _|
 36,582,939 UART: | |   / _` | | | '_ \| __| '__/ _` | | |_) || |
 36,584,379 UART: | |__| (_| | | | |_) | |_| | | (_| | |  _ < | |
 36,585,819 UART:  \____\__,_|_|_| .__/ \__|_|  \__,_| |_| \_\|_|
 36,587,259 UART:                |_|
 36,587,835 UART: 
 36,683,846 UART: Caliptra RT listening for mailbox commands...

Valid LMS key full log

      6,155 ready_for_fuses is high
      6,329 writing to cptra_bootfsm_go
test smoke_test has been running for over 60 seconds
    195,190 UART: 
    195,243 UART: Running Caliptra ROM ...
    196,597 UART: 
    197,158 UART: [state] CFI Enabled
    198,752 UART: [state] LifecycleState = Production
    200,771 UART: [state] DebugLocked = Yes
    202,570 UART: [state] Starting the Watchdog Timer
    341,950 UART: ROM Digest: CB67881D71F3CBB3250029F1D6D2E9E5E6C9359CEB0DF294A264A0CFAE822240
    353,453 UART: [kat] ++
    353,975 UART: [kat] sha1
    363,170 UART: [kat] SHA2-256
    365,863 UART: [kat] SHA2-384
    369,974 UART: [kat] SHA2-384-ACC
    372,265 UART: [kat] ECC-384
  3,940,304 UART: [kat] HMAC-384
  3,949,825 UART: [kat] LMS
  4,961,828 UART: [kat] --
  4,964,703 UART: [cold-reset] ++
  4,967,310 UART: [idev] ++
  4,967,867 UART: [idev] CDI.KEYID = 6
  4,969,073 UART: [idev] SUBJECT.KEYID = 7
  4,970,493 UART: [idev] UDS.KEYID = 0
  4,987,493 UART: [idev] Erasing UDS.KEYID = 0
  8,253,291 UART: [idev] Using Sha1 for KeyId Algorithm
  8,275,477 UART: [idev] --
  8,279,602 UART: [ldev] ++
  8,280,159 UART: [ldev] CDI.KEYID = 6
  8,281,367 UART: [ldev] SUBJECT.KEYID = 5
  8,282,773 UART: [ldev] AUTHORITY.KEYID = 7
  8,284,311 UART: [ldev] FE.KEYID = 1
  8,296,541 UART: [ldev] Erasing FE.KEYID = 1
 11,578,072 UART: [ldev] Signing Cert with AUTHORITY.KEYID = 7
 15,170,383 UART: [ldev] PUB.X = 842C00AF05ACCCEB14514E2D37B0C3AAA218F15057F1DCB824A214980B744688A0888A0297FA7DC5E1EAD8CA1291DB22
 15,186,798 UART: [ldev] PUB.Y = 9C28EB8678BCE800822C07228F416AE49D218E5DA2F2D1A8A27DC19ADF668A74628999D222B40159D8076FAFBB8C5EDB
 15,203,276 UART: [ldev] SIG.R = 0C1B95861ADA0DF572438E88B23DDD5B2C24C974DF359988CC54E39E3145635A94E3D8196B49164CAD991714C2B18892
 15,219,388 UART: [ldev] SIG.S = 4BEDF2A7DEC9405964ADF4949819FADE2CD785CD0307078F74EA4E5CDDF8D1FAE5380507AB09871344CA288FA6961532
 15,241,256 UART: [ldev] --
 15,247,733 UART: [state] Stopping the Watchdog Timer
 15,250,415 ready_for_fw is high
 15,250,417 <<< Executing mbox cmd 0x46574c44 (53148 bytes) from SoC
 15,250,470 UART: [afmc] Waiting for Commands...
 15,277,261 UART: [afmc] Received Image of size 53148 bytes
 15,281,304 UART: [state] Starting the Watchdog Timer
 15,328,802 UART:                 ---Verify start---
 16,629,205 UART: LMS verify start
 16,630,106 UART: 
 18,496,894 UART: LMS verify complete
 18,497,954 UART: 
 19,789,838 UART: LMS verify start
 19,790,739 UART: 
 21,659,206 UART: LMS verify complete
 21,660,266 UART: 
 21,701,521 UART:                 ---Verify complete---
 21,702,820 UART: [afmc] Image verified using Vendor ECC Key Index 0
 21,870,700 UART: [afmc] Loading FMC at address 0x40000000 len 12672
 21,918,501 UART: [afmc] Loading Runtime at address 0x40004000 len 34592
 22,044,441 >>> mbox cmd response: success
 22,049,117 UART: [afmc] ++
 22,049,686 UART: [afmc] CDI.KEYID = 6
 22,050,880 UART: [afmc] SUBJECT.KEYID = 7
 22,052,298 UART: [afmc] AUTHORITY.KEYID = 5
 25,346,410 UART: [afmc] Signing Cert with AUTHORITY.KEYID = 5
 27,640,538 UART: [afmc] Erasing AUTHORITY.KEYID = 5
 28,947,043 UART: [afmc] PUB.X = 6C12037B7CB703F6B6351E2B58B8C0F74CCA034AB2B32A0F3DFAACB7F4AEE71C92FD200B9139CA9374613BF17916E016
 28,963,488 UART: [afmc] PUB.Y = 2ECF032A99B32BAF5833DB3FB55E2BA3A95E194AA89F2E3062914A96DD4DCC36C4624915475A64ADB5D8BA633BCAC665
 28,980,118 UART: [afmc] SIG.R = C70CCF27E49E9F5C84D7F54A6CB2017370211B3A31AD5D6F82DD681EF3AE4F03A0EAFF90B61A936076D399D2F2E14173
 28,996,350 UART: [afmc] SIG.S = 175F7EF43468584D266EE299FD6E14AC743532E973AF98F265BDE622BD0CEB2124CE0A9D4F1753197DEA890A8C64E529
 29,022,199 UART: [afmc] --
 29,026,462 UART: [cold-reset] --
 29,033,630 UART: [fht] Storing FHT @ 0x50003000
 29,039,881 UART: [state] Stopping the Watchdog Timer
 29,044,748 UART: [state] Locking Datavault
 29,050,546 UART: [state] Locking PCR0 and PCR1
 29,052,165 UART: [state] Locking ICCM
 29,054,526 UART: [exit] Launching FMC @ 0x40000134
 29,063,243 UART: 
 29,063,273 UART: Running Caliptra FMC ...
 29,064,031 UART: 
 29,064,923 UART: [alias rt] Extend RT PCRs
 29,125,409 UART: [alias rt] Extend RT PCRs Done
 29,126,345 UART: [alias rt] Lock RT PCRs
 29,127,075 UART: [alias rt] Lock RT PCRs Done
 29,127,951 UART: [alias rt] Populate DV
 29,128,759 UART: [alias rt] Populate DV Done
 29,129,644 UART: Handoff : FMC CDI: 6
 29,130,312 UART: FMC Alias Private Key: 7
 29,132,126 UART: [alias rt] Derive CDI
 29,132,792 UART: [alias rt] Store in in slot 0x4
 29,166,294 UART: [alias rt] Derive Key Pair
 29,167,115 UART: [alias rt] Store priv key in slot 0x5
 32,405,664 UART: [alias rt] Derive Key Pair - Done
 32,416,567 UART: [alias rt] Signing Cert with AUTHO
 32,417,617 UART:             RITY.KEYID = 7
 34,695,450 UART: [alias rt] Erasing AUTHORITY.KEYID = 7
 34,696,831 UART: [alias rt] PUB.X = B0F69BF99973255C109F0890F9BC901830F62509DDCBE845F15BA0120E0D1917BFB79CF033126E93EAB8367297A71711
 34,703,821 UART: [alias rt] PUB.Y = 331734EF4DADB80206A4C68778F401D93910D009F92817987E2A5124DFD8AC51A71BE7914DD3411C156B051402BD64F7
 34,710,985 UART: [alias rt] SIG.R = 2EA73FF07617F7E3EE6FF2616680D525359DBFC479E69B8C924FA5870E46E1B1858101B4B933249C3B27E27702364AF4
 34,717,952 UART: [alias rt] SIG.S = E0BFA74D6044D9FB824D6AD599CBC5481BF26E4C25F69E1631D634D1C67457138B778E884F5840C40DDABD4B8CB4B220
 36,019,146 UART: 
 36,019,176 UART:   ____      _ _       _               ____ _____
 36,020,646 UART:  / ___|__ _| (_)_ __ | |_ _ __ __ _  |  _ \_   _|
 36,022,146 UART: | |   / _` | | | '_ \| __| '__/ _` | | |_) || |
 36,023,586 UART: | |__| (_| | | | |_) | |_| | | (_| | |  _ < | |
 36,025,026 UART:  \____\__,_|_|_| .__/ \__|_|  \__,_| |_| \_\|_|
 36,026,466 UART:                |_|
 36,027,042 UART: 
 36,123,074 UART: Caliptra RT listening for mailbox commands...

attzonko commented 1 year ago

@andreslagarcavilla @benjamindoron @ArthurHeymans @korran @ericeilertson Is the data from Nick sufficient for the information needed? What else is needed from us to close this issue?

andreslagarcavilla commented 1 year ago

thanks everyone, this is cool. Do I understand correctly that it takes 36 million cycles to get to the mailbox loop? ~90 millis @400Mhz?

nquarton commented 1 year ago

That is my understanding. I've heard the 80-90ms time quoted a few times. (But do note there is also limited command handling in ROM much earlier in the boot for certain scenarios.)

ericeilertson commented 12 months ago

To ensure the maximum verification time requires the candidate OTS signature generation to always start at 0 in the winternitz chain, thus forcing each of our 48 hash chains to always be 16 long. To do this we need to change the implementation of the coefficient function in the LMS driver to always return 0. I'll chat with @korran on how to monkey patch the coefficient function for this test.

chipsalliance / caliptra-sw

Boot time profiling #317