Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

flash.sh: UX and logic fixes #1230

Merged
merged 1 commit into from
Nov 1, 2022
Merged

Conversation

tlaurion
Copy link
Collaborator

@tlaurion tlaurion commented Oct 21, 2022

  • Have Talos II supported by detecting correctly size of mtd chip (not internal: different flashrom output needs to be parsed for chip size)
  • Read SPI content only once: 66% speedup (TOCTOU? Don't think so, nothing should happen in parallel when flashing in single user mode under Heads unless parallel physical attack on flash )
  • Have the main flash_progress loop not break, but break in flash_rom state subcases (otherwise, verifying step was breaking)

Next steps:


EDIT:

@tlaurion
Copy link
Collaborator Author

tlaurion commented Oct 24, 2022

Tested on Talos, works.

@JonathonHall-Purism for obscure reason, 79a8146#diff-e33f7a1603ea94b6a0ff385404e9860ff48e1c5afe2ed5c8e68207d3b39186ccR36 loop was broken (break) before verification step to succeed.

When adding debugging traces after the while true loop exiting too early, IN contained "verifying" instead of "done", which made the whole flash_rom call fail with newer flashrom used under #1222

So to test for regression, my next step is to test on x230 on top of master (this PR) but as said the bad behavior seem to happen on top of newer flashrom, which is to be tested against https://app.circleci.com/pipelines/github/tlaurion/heads/1223/workflows/d6e6e2e8-9425-4ac8-bb16-489f08608bd6 produced roms

Short:

@tlaurion
Copy link
Collaborator Author

tlaurion commented Oct 24, 2022

@JonathonHall-Purism

When adding debugging traces after the while true loop exiting too early, IN contained "verifying" instead of "done", which made the whole flash_rom call fail with newer flashrom used under #1222

If you have better implementation suggestion ( now the main loop doesn't break: the individual parts are responsible for breaking the loop if the state changes or fail. Previously, when no more log were processed, the main loop would break causing the issue).

Otherwise, As said in previous post, regression has been done for this PR and this PR on top of #1222

I would suggest testing Librem boards produced from https://app.circleci.com/pipelines/github/tlaurion/heads/1223/workflows/d6e6e2e8-9425-4ac8-bb16-489f08608bd6/jobs/11148 so you can test flashrom version bump + flash.sh modifications in one shot, unless you have a better imppementation proposal for this PR.

Note: this PR removes flashrom backup of 3 reads, and replaces it with one flashrom -r and one flashrom -v (to verify backuped content against SPI prior of injecting stuff and flashing it back. Newer version of flashrom verifies automatically at flash).
Is that even needed (to do the flashrom -v on internal backup content?) This PR stays on the safer side and still does the verification against backuped rom. But I never saw, personally, a backuped ROM through -p internal having different content across reads. I do not recollect exactly why the 3 reads were integrated into Heads as if we were doing external backups with unreliable programmer, but even there, documentation has been updated to use flashrom verification mode instead of reading 3 times.

Your call on keeping my code suggestion to verify rom content, or go more radical into removing flashrom -v completely and just using the backup content to persist content (cbfs injection) prior of flashing back at firmware upgrades, key injection etc.

@tlaurion
Copy link
Collaborator Author

tlaurion commented Oct 25, 2022

@JonathonHall-Purism further tests shows that a loooooooot of time is wasted into calculating and drawing a progress bar through bashisms, while latest flashrom actually draws a progress natively with --progress command line option.

Putting this PR as draft. the current implementation under flash.sh is not fit for larger flash chips as can be seen below in user time comparison, time spent doing irrelevant work (Talos II 64mb flash chip here).

Standard without flash.sh progress bar, calling flashrom directly and dismissing any output on serial console:

time flashrom $CONFIG_FLASHROM_OPTIONS -V -o /tmp/log -w /tmp/backup.rom > /tmp/progress
real    0m 26.70s
user    0m 0.68s
sys     0m 25.68s

With actual flash.sh from this PR (still doing unneeded verification on flash chip content):

time flash.sh -c /tmp/backup.rom
Board talos-2_server detected, continuing...
c31715cc9b846227c78e7aadfb3fb3473c7660b24007050c900338c526bcc37d  /tmp/talos-2_server.rom

Initializing internal Flash Programmer
Total flash size : 67108864 bytes
Reading old flash contents. Please wait...
Flashing: [##################################################] (100%)
The flash contents are identical to the image being flashed.

real    1m 40.56s
user    0m 37.77s
sys     1m 19.45s

@tlaurion tlaurion marked this pull request as draft October 25, 2022 17:50
@tlaurion
Copy link
Collaborator Author

tlaurion commented Oct 25, 2022

Solution is to have native progress bar of latest flashrom, which means having ast1100 (kgpe-d16 bmc flashing support) that is still a patch under heads against used version of flashrom.

This will should lan under https://github.com/Dasharo/flashrom, which should be used anyway for wp wp-status and other improvements from parallel work

@JonathonHall-Purism
Copy link
Collaborator

Hey @tlaurion, I think these are good directions.

I agree we should move toward the native flashrom progress rather than the bashisms, I think this is also the source of very long flash times on Librem Server (several minutes for 16 MB flash IIRC).

However, the progress indicator in the latest flashrom is relatively crude, it just dumps percentage updates to one long line. At least a line break (and maybe reducing frequency to 5% so it doesn't wipe out the whole terminal) would be nice, actually resetting the position in the terminal would be even better. I'd be happy to look into that in flashrom eventually, but right now my to-do list is growing faster than I can keep up with it.
image

If you don't want to get into flashrom, maybe a middle ground would be to drop the 'spinner' from the bashism progress bar and use the 'progress' interface to feed it? That might be a bit more stable, and it only prints every 1%; it doesn't scale up with flash chip size.

I'll test this on Librem boards to verify the flashrom update this week too.

Re: additional improvements - the only suggestion I have would be to potentially just flash modified regions when changing settings - i.e. just flash the CBFS region when that's all that's needed, to avoid reading and verifying the rest of flash. Or even better, to move config, GPG keyring, etc., to their own region, so we could separate them from the payload too. There's no need to tie that to this work though.

@tlaurion
Copy link
Collaborator Author

@JonathonHall-Purism well... I took dasharo/flashrom and started trying to tackle with the flash.sh script to deal with only refresh on the same line some kind of progress, to realise that there is an issue upstream on master, stating that on erase/write operations, the output goes backward (so writing progress jumps from 100% to 0%)....
https://ticket.coreboot.org/issues/390

Re: additional improvements - the only suggestion I have would be to potentially just flash modified regions when changing settings - i.e. just flash the CBFS region when that's all that's needed, to avoid reading and verifying the rest of flash. Or even better, to move config, GPG keyring, etc., to their own region, so we could separate them from the payload too. There's no need to tie that to this work though.

That deserves separate issues and definitely are awesome ideas to debate prior of implementing. I see some issues there though, since some firmware upgrades might include new stuff in cbfs and bootblock might change as well. I do not see a problem, really, into the current process when upgrading while keeping persistence:

  • have cbfs content extracted
  • have the to be flashed rom copied from source to have operations, have cbfs content injected in copy
  • have flashrom (internal ops on write) take a backup, compare it with full image
  • Erase/write only blocks that changed.

The same process above is used when deciding to wipe GPG public and keyring+trustdb+config.user injected back (with other type 50 cbfs files in current rom), where above operations only change between the source of the rom being a backup of current prior of copying it over for change and flashed back.

I understand on my side (and for developers) that it is a burden when devlopping, but that is another subject of interest which should be linked with having pflash/mtd/qemu/kvm internal flashing support, which would definitely ease testing those sorta thing!
@JonathonHall-Purism: Any update on qemu/kvm internal flashing requirements that are missing?

@tlaurion tlaurion force-pushed the flash_sh-fixes branch 5 times, most recently from f79100b to 9160149 Compare October 26, 2022 21:20
@tlaurion
Copy link
Collaborator Author

tlaurion commented Oct 26, 2022

@JonathonHall-Purism : modified OP.

Flashing backup after having injected key:

~ # time flash.sh -c /tmp/backup.rom 
Board talos-2_server detected, continuing...
724da81a21f40dba12747b21ebc9b1719d197f579ad128ac642a8a0e86504923  /tmp/talos-2_server.rom

Initializing internal Flash Programmer
Total flash size : 65536 kB

Reading old flash contents. Please wait...
Reading: 100%
Flashing ROM content. Please wait...
Flashing: 100%
Verifying flash contents. Please wait...
The flash contents were verified and the image was flashed correctly.

real	1m 6.20s
user	0m 4.15s
sys	1m 3.61s

Note: the output of Flashing stays to 100%, which seems to be the result of https://ticket.coreboot.org/issues/390

Redoing manually:

~ # flashrom $CONFIG_FLASHROM_OPTIONS --progress -w /tmp/gpg-gui.rom
flashrom  on Linux 5.5.0-openpower1 (ppc64le)
flashrom is free software, get the source code at https://flashrom.org

Using clock_gettime for delay loops (clk_id: 1, resolution: 1ns).
Opened /dev/mtd0 successfully
Found Programmer flash chip "Opaque flash chip" (65536 kB, Programmer-specific) on linux_mtd.
Reading old flash chip contents... [READ] 0% complete... [READ] 1% complete... [READ] 2% complete... [READ] 3% complete... [READ] 4% complete... [READ] 5% complete... [READ] 6% complete... [READ] 7% complete... [READ] 8% complete... [READ] 9% complete... [READ] 10% complete... [READ] 11% complete... [READ] 12% complete... [READ] 13% complete... [READ] 14% complete... [READ] 15% complete... [READ] 16% complete... [READ] 17% complete... [READ] 18% complete... [READ] 19% complete... [READ] 20% complete... [READ] 21% complete... [READ] 22% complete... [READ] 23% complete... [READ] 24% complete... [READ] 25% complete... [READ] 26% complete... [READ] 27% complete... [READ] 28% complete... [READ] 29% complete... [READ] 30% complete... [READ] 31% complete... [READ] 32% complete... [READ] 33% complete... [READ] 34% complete... [READ] 35% complete... [READ] 36% complete... [READ] 37% complete... [READ] 38% complete... [READ] 39% complete... [READ] 40% complete... [READ] 41% complete... [READ] 42% complete... [READ] 43% complete... [READ] 44% complete... [READ] 45% complete... [READ] 46% complete... [READ] 47% complete... [READ] 48% complete... [READ] 49% complete... [READ] 50% complete... [READ] 51% complete... [READ] 52% complete... [READ] 53% complete... [READ] 54% complete... [READ] 55% complete... [READ] 56% complete... [READ] 57% complete... [READ] 58% complete... [READ] 59% complete... [READ] 60% complete... [READ] 61% complete... [READ] 62% complete... [READ] 63% complete... [READ] 64% complete... [READ] 65% complete... [READ] 66% complete... [READ] 67% complete... [READ] 68% complete... [READ] 69% complete... [READ] 70% complete... [READ] 71% complete... [READ] 72% complete... [READ] 73% complete... [READ] 74% complete... [READ] 75% complete... [READ] 76% complete... [READ] 77% complete... [READ] 78% complete... [READ] 79% complete... [READ] 80% complete... [READ] 81% complete... [READ] 82% complete... [READ] 83% complete... [READ] 84% complete... [READ] 85% complete... [READ] 86% complete... [READ] 87% complete... [READ] 88% complete... [READ] 89% complete... [READ] 90% complete... [READ] 91% complete... [READ] 92% complete... [READ] 93% complete... [READ] 94% complete... [READ] 95% complete... [READ] 96% complete... [READ] 97% complete... [READ] 98% complete... [READ] 99% complete... [READ] 100% complete... done.
Erasing and writing flash chip... [ERASE] 100% complete... [WRITE] 100% complete... 



....long wait without input here....



Erase/write done.
Verifying flash... [READ] 0% complete... [READ] 1% complete... [READ] 2% complete... [READ] 3% complete... [READ] 4% complete... [READ] 5% complete... [READ] 6% complete... [READ] 7% complete... [READ] 8% complete... [READ] 9% complete... [READ] 10% complete... [READ] 11% complete... [READ] 12% complete... [READ] 13% complete... [READ] 14% complete... [READ] 15% complete... [READ] 16% complete... [READ] 17% complete... [READ] 18% complete... [READ] 19% complete... [READ] 20% complete... [READ] 21% complete... [READ] 22% complete... [READ] 23% complete... [READ] 24% complete... [READ] 25% complete... [READ] 26% complete... [READ] 27% complete... [READ] 28% complete... [READ] 29% complete... [READ] 30% complete... [READ] 31% complete... [READ] 32% complete... [READ] 33% complete... [READ] 34% complete... [READ] 35% complete... [READ] 36% complete... [READ] 37% complete... [READ] 38% complete... [READ] 39% complete... [READ] 40% complete... [READ] 41% complete... [READ] 42% complete... [READ] 43% complete... [READ] 44% complete... [READ] 45% complete... [READ] 46% complete... [READ] 47% complete... [READ] 48% complete... [READ] 49% complete... [READ] 50% complete... [READ] 51% complete... [READ] 52% complete... [READ] 53% complete... [READ] 54% complete... [READ] 55% complete... [READ] 56% complete... [READ] 57% complete... [READ] 58% complete... [READ] 59% complete... [READ] 60% complete... [READ] 61% complete... [READ] 62% complete... [READ] 63% complete... [READ] 64% complete... [READ] 65% complete... [READ] 66% complete... [READ] 67% complete... [READ] 68% complete... [READ] 69% complete... [READ] 70% complete... [READ] 71% complete... [READ] 72% complete... [READ] 73% complete... [READ] 74% complete... [READ] 75% complete... [READ] 76% complete... [READ] 77% complete... [READ] 78% complete... [READ] 79% complete... [READ] 80% complete... [READ] 81% complete... [READ] 82% complete... [READ] 83% complete... [READ] 84% complete... [READ] 85% complete... [READ] 86% complete... [READ] 87% complete... [READ] 88% complete... [READ] 89% complete... [READ] 90% complete... [READ] 91% complete... [READ] 92% complete... [READ] 93% complete... [READ] 94% complete... [READ] 95% complete... [READ] 96% complete... [READ] 97% complete... [READ] 98% complete... [READ] 99% complete... [READ] 100% complete... VERIFIED.

Then reflashing with clean just for good measure:

~ # time flash.sh -c /tmp/backup.rom 
Board talos-2_server detected, continuing...
724da81a21f40dba12747b21ebc9b1719d197f579ad128ac642a8a0e86504923  /tmp/talos-2_server.rom

Initializing internal Flash Programmer
Total flash size : 65536 kB

Reading old flash contents. Please wait...
Reading: 100%
Flashing ROM content. Please wait...
Flashing: 100%
Verifying flash contents. Please wait...
The flash contents were verified and the image was flashed correctly.

real	1m 10.51s
user	0m 4.12s
sys	1m 8.00s
~ # time flashrom $CONFIG_FLASHROM_OPTIONS --progress -w /tmp/gpg-gui.rom
flashrom  on Linux 5.5.0-openpower1 (ppc64le)
flashrom is free software, get the source code at https://flashrom.org

Using clock_gettime for delay loops (clk_id: 1, resolution: 1ns).
Opened /dev/mtd0 successfully
Found Programmer flash chip "Opaque flash chip" (65536 kB, Programmer-specific) on linux_mtd.
Reading old flash chip contents... [READ] 0% complete... [READ] 1% complete... [READ] 2% complete... [READ] 3% complete... [READ] 4% complete... [READ] 5% complete... [READ] 6% complete... [READ] 7% complete... [READ] 8% complete... [READ] 9% complete... [READ] 10% complete... [READ] 11% complete... [READ] 12% complete... [READ] 13% complete... [READ] 14% complete... [READ] 15% complete... [READ] 16% complete... [READ] 17% complete... [READ] 18% complete... [READ] 19% complete... [READ] 20% complete... [READ] 21% complete... [READ] 22% complete... [READ] 23% complete... [READ] 24% complete... [READ] 25% complete... [READ] 26% complete... [READ] 27% complete... [READ] 28% complete... [READ] 29% complete... [READ] 30% complete... [READ] 31% complete... [READ] 32% complete... [READ] 33% complete... [READ] 34% complete... [READ] 35% complete... [READ] 36% complete... [READ] 37% complete... [READ] 38% complete... [READ] 39% complete... [READ] 40% complete... [READ] 41% complete... [READ] 42% complete... [READ] 43% complete... [READ] 44% complete... [READ] 45% complete... [READ] 46% complete... [READ] 47% complete... [READ] 48% complete... [READ] 49% complete... [READ] 50% complete... [READ] 51% complete... [READ] 52% complete... [READ] 53% complete... [READ] 54% complete... [READ] 55% complete... [READ] 56% complete... [READ] 57% complete... [READ] 58% complete... [READ] 59% complete... [READ] 60% complete... [READ] 61% complete... [READ] 62% complete... [READ] 63% complete... [READ] 64% complete... [READ] 65% complete... [READ] 66% complete... [READ] 67% complete... [READ] 68% complete... [READ] 69% complete... [READ] 70% complete... [READ] 71% complete... [READ] 72% complete... [READ] 73% complete... [READ] 74% complete... [READ] 75% complete... [READ] 76% complete... [READ] 77% complete... [READ] 78% complete... [READ] 79% complete... [READ] 80% complete... [READ] 81% complete... [READ] 82% complete... [READ] 83% complete... [READ] 84% complete... [READ] 85% complete... [READ] 86% complete... [READ] 87% complete... [READ] 88% complete... [READ] 89% complete... [READ] 90% complete... [READ] 91% complete... [READ] 92% complete... [READ] 93% complete... [READ] 94% complete... [READ] 95% complete... [READ] 96% complete... [READ] 97% complete... [READ] 98% complete... [READ] 99% complete... [READ] 100% complete... done.
Erasing and writing flash chip... [ERASE] 100% complete... [WRITE] 100% complete... Erase/write done.
Verifying flash... [READ] 0% complete... [READ] 1% complete... [READ] 2% complete... [READ] 3% complete... [READ] 4% complete... [READ] 5% complete... [READ] 6% complete... [READ] 7% complete... [READ] 8% complete... [READ] 9% complete... [READ] 10% complete... [READ] 11% complete... [READ] 12% complete... [READ] 13% complete... [READ] 14% complete... [READ] 15% complete... [READ] 16% complete... [READ] 17% complete... [READ] 18% complete... [READ] 19% complete... [READ] 20% complete... [READ] 21% complete... [READ] 22% complete... [READ] 23% complete... [READ] 24% complete... [READ] 25% complete... [READ] 26% complete... [READ] 27% complete... [READ] 28% complete... [READ] 29% complete... [READ] 30% complete... [READ] 31% complete... [READ] 32% complete... [READ] 33% complete... [READ] 34% complete... [READ] 35% complete... [READ] 36% complete... [READ] 37% complete... [READ] 38% complete... [READ] 39% complete... [READ] 40% complete... [READ] 41% complete... [READ] 42% complete... [READ] 43% complete... [READ] 44% complete... [READ] 45% complete... [READ] 46% complete... [READ] 47% complete... [READ] 48% complete... [READ] 49% complete... [READ] 50% complete... [READ] 51% complete... [READ] 52% complete... [READ] 53% complete... [READ] 54% complete... [READ] 55% complete... [READ] 56% complete... [READ] 57% complete... [READ] 58% complete... [READ] 59% complete... [READ] 60% complete... [READ] 61% complete... [READ] 62% complete... [READ] 63% complete... [READ] 64% complete... [READ] 65% complete... [READ] 66% complete... [READ] 67% complete... [READ] 68% complete... [READ] 69% complete... [READ] 70% complete... [READ] 71% complete... [READ] 72% complete... [READ] 73% complete... [READ] 74% complete... [READ] 75% complete... [READ] 76% complete... [READ] 77% complete... [READ] 78% complete... [READ] 79% complete... [READ] 80% complete... [READ] 81% complete... [READ] 82% complete... [READ] 83% complete... [READ] 84% complete... [READ] 85% complete... [READ] 86% complete... [READ] 87% complete... [READ] 88% complete... [READ] 89% complete... [READ] 90% complete... [READ] 91% complete... [READ] 92% complete... [READ] 93% complete... [READ] 94% complete... [READ] 95% complete... [READ] 96% complete... [READ] 97% complete... [READ] 98% complete... [READ] 99% complete... [READ] 100% complete... VERIFIED.
real	1m 10.98s
user	0m 1.70s
sys	1m 8.99s

Is that satisfying? As current state, when flashing so little content, there is a pause of 5 seconds between:
Erasing and writing flash chip... [ERASE] 100% complete... and [WRITE] 100% complete... Erase/write done.

It might be worrying to some, unfortunately. Otherwise, the script does what is expected and the progress of reading and verifying is actually an upgrade as currently under master.

Let me know what you think, and if you think we should wait for https://ticket.coreboot.org/issues/390 to be fixed.

@tlaurion
Copy link
Collaborator Author

tlaurion commented Oct 27, 2022

With 76d7ee5:

~ # flash.sh -c /tmp/backup.rom 
Board talos-2_server detected, continuing...
5845d0bdf20a6705a62c5b59d2ad4054d0eae7a7c4c93b35a69be4c5ab8c53b7  /tmp/talos-2_server.rom

Initializing internal Flash Programmer
Total flash size : 65536 kB

Reading old flash contents. Please wait...
Reading: 100%
Flashing ROM content. Please wait...
Flashing: 100%
Verifying flash contents. Please wait...
Verifying: 100%
The flash contents were verified and the image was flashed correctly.

But the flashing operations (which encompasses ERASE and WRITE --progress output reports) is bogus.
Flashing: 100% above starts at 100% and stays at 100% for 12 seconds without giving any update.

So as long as master doesn't change its flashrom --progress output to be useful, I think we should stick to current flashrom version (otherwise causing regression for BMC ast1100 flashing) and worrying users at flash time because lack of flashing progress, which master does correctly at the cost of loosing up to 30 seconds, parsing flashrom verbose (-V output).

Will propose bug fix, single read backup in this PR, and we can refer to next round of fixes by comparing this PR to the fixes proposed under 76d7ee5 at a later time.

@tlaurion
Copy link
Collaborator Author

@JonathonHall-Purism : The working fix for this is under 642338e above:

- Have Talos II supported by detecting correctly size of mtd chip (not internal: different flashrom output needs to be parsed for chip size)
- Read SPI content only once: 66% speedup (TOCTOU? Don't think so, nothing should happen in parallel when flashing insingle user mode)
- Have the main lfash_progress loop not break, but break in flash_rom state subcases (otherwise, verifying step was breaking)

Will modify OP accordingly, leaving a trace pointing to 76d7ee5 for later work (after flashrom fixes its --progress reporting)

As of today, on Talos II (after having called gpg-gui.sh to prepare firmware image with new gpg keyring + trustdb injected in rom to be flashed):

~ # time flash.sh -c /tmp/gpg-gui.rom 
Board talos-2_server detected, continuing...
767c450f17e31b8a69c56bb485b0d19e2672acf0a3ed20e3b23be8dfa70c04ce  /tmp/talos-2_server.rom

Initializing internal Flash Programmer
Total flash size : 67108864 bytes
Reading old flash contents. Please wait...
Flashing: [##################################################] (100%)
Verifying flash contents. Please wait...
The flash contents were verified and the image was flashed correctly.

real	2m 7.37s
user	0m 43.00s
sys	2m 15.84s

We can see that processing the output of flashrom -V takes 43 seconds for 64mb spi chip in with mtd programmer, which relates to your librem server use case.

I think this is best solution as of today.

@JonathonHall-Purism Please review!
@SergiiDmytruk : once this is merged, #1222 will be functional and should be rebased on master after merging.

@tlaurion
Copy link
Collaborator Author

tlaurion commented Oct 28, 2022

@JonathonHall-Purism ready for review, should not cause any regression.
No more 3 read of rom, no more verify, and bugfix for Talos, no version bumps.

As you said, we could tweak this further, but as noted under #1222 (comment), percentage jams on boards with more SPI, and the current progress bar changes is the only hint to the user that something is still happening while those ERASE+WRITE are happening.

My call on this would be to keep those changes seperate, and version bump flashrom when flashrom fixes the behavior upstream prior of touching that code, revisiting 76d7ee5 later on.

@tlaurion tlaurion marked this pull request as ready for review October 28, 2022 18:14
@SergiiDmytruk
Copy link
Contributor

The slowdown is larger than user time (1m 41s vs. 26s):

~ # time flash.sh /tmp/backup
Board talos-2_server detected, continuing...
dab360db4990a65ea79e1df95bf2b9cc27ff8d72c77895052b6bed0fddde1045  /tmp/talos-2_server.rom

Initializing internal Flash Programmer
Total flash size : 67108864 bytes
Reading old flash contents. Please wait...
Flashing: [##################################################] (100%)
The flash contents are identical to the image being flashed.

real    1m 41.05s
user    0m 36.15s
sys     1m 17.48s
~ # time flashrom $CONFIG_FLASHROM_OPTIONS -w /tmp/backup
flashrom  on Linux 5.5.0-openpower1 (ppc64le)
flashrom is free software, get the source code at https://flashrom.org

Using clock_gettime for delay loops (clk_id: 1, resolution: 1ns).
Opened /dev/mtd0 successfully
Found Programmer flash chip "Opaque flash chip" (65536 kB, Programmer-specific) on linux_mtd.
Reading old flash chip contents... done.
Erasing and writing flash chip...
Warning: Chip content is identical to the requested image.
Erase/write done.
real    0m 26.41s
user    0m 0.56s
sys     0m 25.48s

Either flashrom process gets blocked in kernel space when pipe fills up while shell is doing its work, or flashrom is done in 30s after which you're watching progress of text processing :)

With:

diff --git a/initrd/bin/flash.sh b/initrd/bin/flash.sh
index 66cce75..35812f6 100755
--- a/initrd/bin/flash.sh
+++ b/initrd/bin/flash.sh
@@ -27,6 +27,8 @@ flashrom_progress() {
     local status='init'
     local prev_word=''
     local prev_prev_word=''
+    local spaces='                                                  '
+    local hashes='##################################################'
 
     progressbar2=$(for i in `seq 48` ; do echo -ne ' ' ; done)
     echo -e "\nInitializing internal Flash Programmer"
@@ -35,13 +37,13 @@ flashrom_progress() {
         prev_word=$IN
         read -r -d' ' IN
         if [ "$total_bytes" != "0" ]; then
-            current=$(echo "$IN" | grep -E -o '0x[0-9a-f]+-0x[0-9a-f]+:.*' | grep -E -o "0x[0-9a-f]+" | tail -n 1)
+            current=$(echo "$IN" | sed -nE 's/.*(0x[0-9a-f]+).*/\1/p')
             if [ "${current}" != "" ]; then
                 percent=$((100 * (current + 1) / total_bytes))
                 pct1=$((percent / 2))
-                pct2=$((49 - percent / 2))
-                progressbar=$(for i in `seq $pct1 2>/dev/null` ; do echo -ne '#' ; done)
-                progressbar2=$(for i in `seq $pct2 2>/dev/null` ; do echo -ne ' ' ; done)
+                pct2=$((50 - percent / 2))
+                progressbar=${hashes:0:$pct1}
+                progressbar2=${spaces:0:$pct2}
             fi
         else
             if [ "$prev_prev_word"  == "Reading" ] && [ "$IN" == "bytes" ]; then

Things somewhat improve:

~ # time flash.sh -c /tmp/backup
Board talos-2_server detected, continuing...
dab360db4990a65ea79e1df95bf2b9cc27ff8d72c77895052b6bed0fddde1045  /tmp/talos-2_server.rom

Initializing internal Flash Programmer
Total flash size : 67108864 bytes
Reading old flash contents. Please wait...
Flashing: [##################################################] (100%)
The flash contents are identical to the image being flashed.

real    1m 7.12s
user    0m 17.34s
sys     0m 49.90s

By the way, the script prints "Initializing internal Flash Programmer", this might be worth changing.

- Have Talos II supported by detecting correctly size of mtd chip (not internal: different flashrom output needs to be parsed for chip size)
- Read SPI content only once: 66% speedup (TOCTOU? Don't think so, nothing should happen in parallel when flashing insingle user mode)
- Have the main flash_progress loop not break, but break in flash_rom state subcases (otherwise, verifying step was breaking)
- Change "Initializing internal Flash Programmer" -> "Initializing Flash Programmer"
- Apply changes suggested by @SergiiDmytruk under linuxboot#1230 (comment) to reduce userland wasted time processing flashrom -V output
tlaurion added a commit to tlaurion/heads that referenced this pull request Oct 28, 2022
- Have Talos II supported by detecting correctly size of mtd chip (not internal: different flashrom output needs to be parsed for chip size)
- Read SPI content only once: 66% speedup (TOCTOU? Don't think so, nothing should happen in parallel when flashing insingle user mode)
- Have the main flash_progress loop not break, but break in flash_rom state subcases (otherwise, verifying step was breaking)
- Change "Initializing internal Flash Programmer" -> "Initializing Flash Programmer"
- Apply changes suggested by @SergiiDmytruk under linuxboot#1230 (comment) to reduce userland wasted time processing flashrom -V output
@tlaurion
Copy link
Collaborator Author

tlaurion commented Oct 28, 2022

Thanks a lot @SergiiDmytruk for the suggestions. That is sufficient performance enhancement until flashrom produces useful --progress reporting and fixes https://ticket.coreboot.org/issues/390 so that the progress can be used as is without hacking around it.

This PR updated with your suggestions, while building on top of #1222 as said under #1222 (comment).

@tlaurion
Copy link
Collaborator Author

tlaurion commented Oct 31, 2022

@JonathonHall-Purism Outside of getting weird time calculations that I do not comprehend as of now:
2022-10-31-150045
(How can user>real?!?! This is weird.... But oh well.)

This is massive improvement and fits the goal. Please review/approve when you have a minute in link with OP updated changes and commit message: #1230 (comment)


Future work from your notes above should be opened in different issues:

additional improvements - the only suggestion I have would be to potentially just flash modified regions when changing settings - i.e. just flash the CBFS region when that's all that's needed, to avoid reading and verifying the rest of flash. Or even better, to move config, GPG keyring, etc., to their own region, so we could separate them from the payload too. There's no need to tie that to this work though.

@tlaurion
Copy link
Collaborator Author

@JonathonHall-Purism :

Comparison before above proposed fix by @SergiiDmytruk :

~ # time flash.sh -c /tmp/backup 
Board talos-2_server detected, continuing...
a564ec597322fd4448cf8d3d57507a80e4ff8d67381798bc0de54e1109a6c076  /tmp/talos-2_server.rom

Initializing internal Flash Programmer
Total flash size : 67108864 bytes
Reading old flash contents. Please wait...
Flashing: [##################################################] (100%)
Verifying flash contents. Please wait...
The flash contents were verified and the image was flashed correctly.
real	2m 2.07s
user	0m 42.74s
sys	2m 12.43s

After:

~ # time flash.sh -c /tmp/backup 
Board talos-2_server detected, continuing...
2a7aea18d12a5fe38fa2c51918f218686f8d894eef8e2a988d2e69cf6d0604ab  /tmp/talos-2_server.rom

Initializing Flash Programmer
Total flash size : 67108864 bytes
Reading old flash contents. Please wait...
Flashing: [##################################################] (100%)
Verifying flash contents. Please wait...
The flash contents were verified and the image was flashed correctly.

real	1m 30.67s
user	0m 18.26s
sys	1m 41.92s
~ # time flash.sh -c /tmp/gpg-gui.rom 
Board talos-2_server detected, continuing...
9d94288318669b4d3072df904f39fdedabbc5b01de4966d4c28bcce8fe633c6b  /tmp/talos-2_server.rom

Initializing Flash Programmer
Total flash size : 67108864 bytes
Reading old flash contents. Please wait...
Flashing: [##################################################] (100%)
Verifying flash contents. Please wait...
The flash contents were verified and the image was flashed correctly.

real	1m 30.75s
user	0m 18.32s
sys	1m 42.71s

@JonathonHall-Purism
Copy link
Collaborator

I think this looks great! Thanks @tlaurion, I think we have a lot of good future ideas above but this is a great improvement on its own. Let's ship it 💯

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants