Regression booting rpi3/4 with U-Boot on recent firmware

[nullr0ute]

Describe the bug
Moving Fedora from firmware 7208c3d to 25e2b59 without any other changes has regressed booting with U-Boot on Fedora.

It stops the RPi3 from booting at all and the RPi4 boots but extremely slowly. The F-34 U-Boot for RPi-3 and RPi-4

To reproduce

U-Boot 2021.04 (Apr 21 2021 - 00:00:00 +0000)

DRAM:  992 MiB
RPI 3 Model B+ (0xa020d3)
MMC:   sdhci_setup_cfg: Hardware doesn't specify base clock frequency
sdhci_setup_cfg: Hardware doesn't specify base clock frequency
mmcnr@7e300000 - probe failed: -22
mmc@7e202000: 0sdhci_setup_cfg: Hardware doesn't specify base clock frequency

Loading Environment from FAT... fsm 1, hsts 00000080
read timeout error - HSTS 00000080
WARNING at drivers/mmc/bcm2835_sdhost.c:414/bcm2835_send_command()!
WARNING at drivers/mmc/bcm2835_sdhost.c:382/bcm2835_prepare_data()!
WARNING at drivers/mmc/bcm2835_sdhost.c:414/bcm2835_send_command()!
WARNING at drivers/mmc/bcm2835_sdhost.c:414/bcm2835_send_command()!
unable to select a mode
In:    serial
Out:   vidconsole
Err:   vidconsole
Net:   No ethernet found.
starting USB...
Bus usb@7e980000: USB DWC2
scanning bus usb@7e980000 for devices... 4 USB Device(s) found
       scanning usb for storage devices... 0 Storage Device(s) found
Hit any key to stop autoboot:  0 
WARNING at drivers/mmc/bcm2835_sdhost.c:414/bcm2835_send_command()!
fsm 1, hsts 00000080
read timeout error - HSTS 00000080
WARNING at drivers/mmc/bcm2835_sdhost.c:414/bcm2835_send_command()!
WARNING at drivers/mmc/bcm2835_sdhost.c:382/bcm2835_prepare_data()!
WARNING at drivers/mmc/bcm2835_sdhost.c:414/bcm2835_send_command()!
WARNING at drivers/mmc/bcm2835_sdhost.c:414/bcm2835_send_command()!
unable to select a mode
no mmc device at slot 1

Device 0: unknown device
lan78xx_eth Waiting for PHY auto negotiation to complete...... done
BOOTP broadcast 1
DHCP client bound to address 192.168.0.39 (4 ms)
Using lan78xx_eth device
TFTP from server 192.168.0.20; our IP address is 192.168.0.39

Expected behaviour
No "sdhci_setup_cfg: Hardware doesn't specify base clock frequency" errors and timeouts reading from the MMC

Actual behaviour
Timeouts on the mSD slot

System
Vanilla F-34 with just the RPi firmware updated.

• Which model of Raspberry Pi? RPi3b/RPi3B+/RPi4
• Which OS and version (cat /etc/rpi-issue)? Fedora release 34 (Thirty Four)
• Which firmware version (vcgencmd version)? 2021-08-19T12:27:51 - 25e2b59
• Which kernel version (uname -a)? 5.13.12-200.fc34.aarch64

Logs
Included above

Additional context

Looks most like the following but I will be checking all the in between builds:

firmware: arm_loader: Make most arm clock requests required
See: https://github.com/raspberrypi/firmware/issues/1598

[vfazio]

Confirming this issue... SD card throughput plummets with recent firmware.

From u-boot 2021.07 with rpi_arm64_defconfig:

fatload mmc 0:1 ${kernel_addr_r} <image>

Currently:

5259877 bytes read in 44908 ms (114.3 KiB/s)
   Uncompressing Kernel Image

Previously:

5259877 bytes read in 226 ms (22.2 MiB/s)
   Uncompressing Kernel Image

the current 1.20210831 tag is affected, 1.20210805 is not.

25e2b59 seems to introduce the issue. 69cfd9f is not affected.

Works:

root@rpi-87fa00:~# vcdbg version
vcos_build_version     = 046501ae7f6bb2bb270f609d764be02a5fb2cf65 (clean)
vcos_build_branch      = bcm2711_2
debug_sym: ReadVideoCoreMemoryBySymbol: Symbol not found: 'vcos_build_application'
vcos_build_application = ?
vcos_build_date        = Aug 18 2021
vcos_build_time        = 12:56:16
vcos_build_user        = dom
vcos_build_hostname    = buildbot
vcos_build_platform    = raspberrypi_linux
debug_sym: ReadVideoCoreMemoryBySymbol: Symbol not found: 'vcos_build_type'
vcos_build_type        = ?

affected:

root@rpi-87fa00:~# vcdbg
vcdbg - no command specified
root@rpi-87fa00:~# vcdbg version
vcos_build_version     = ef2c018dccdeb94b0376db62a2ea4c882f9b500d (clean)
vcos_build_branch      = bcm2711_2
debug_sym: ReadVideoCoreMemoryBySymbol: Symbol not found: 'vcos_build_application'
vcos_build_application = ?
vcos_build_date        = Aug 19 2021
vcos_build_time        = 12:28:18
vcos_build_user        = dom
vcos_build_hostname    = buildbot
vcos_build_platform    = raspberrypi_linux
debug_sym: ReadVideoCoreMemoryBySymbol: Symbol not found: 'vcos_build_type'
vcos_build_type        = ?

[jlinton]

This is hitting the latest edk2 builds as well. I debugged it a bit in uboot last week and the mailbox is returning a 0 clock rate. I need to see if the mailbox structure changed/whatever but I'm away from the pi's today.

[pelwell]

Any further information you can provide about the clock in question and the circumstances surrounding the 0 rate would be appreciated.

[vfazio]

@pelwell

I put some print statements in u-boot:

MMC:   bcm2835: clk: 4 clkstate: 1
MMC:   bcm2835: clk: 4 clkrate: 0
mmc@7e202000: 0
Loading Environment from FAT... slow clock: set cdiv: 2047
slow clock: set cdiv: 2047
slow clock: set cdiv: 2047
slow clock: set cdiv: 2047
slow clock: set cdiv: 2047
OK
In:    serial
Out:   vidconsole
Err:   vidconsole
Net:   No ethernet found.
starting USB...
Bus usb@7e980000: usb dr_mode not found
USB DWC2
scanning bus usb@7e980000 for devices...
Warning: smsc95xx_eth (eth0) using random MAC address - 52:40:40:f3:94:cb
4 USB Device(s) found
       scanning usb for storage devices... 0 Storage Device(s) found
Hit any key to stop autoboot:  0
U-Boot> mmcinfo
Device: mmc@7e202000
Manufacturer ID: 3
OEM: 5344
Name: SC32G
Bus Speed: 0
Mode: SD High Speed (50MHz)
Rd Block Len: 512
SD version 3.0
High Capacity: Yes
Capacity: 29.7 GiB
Bus Width: 4-bit
Erase Group Size: 512 Bytes

on previous firmware:

MMC:   bcm2835: clk: 4 clkstate: 1
MMC:   bcm2835: clk: 4 clkrate: 250000000
mmc@7e202000: 0
Loading Environment from FAT... slow clock: set cdiv: 2047
slow clock: set cdiv: 2047
sdhost: mmclock: 122129
sdhost: set cdiv: 2045
sdhost: mmclock: 50000000
sdhost: set cdiv: 3
OK
In:    serial
Out:   vidconsole
Err:   vidconsole
Net:   No ethernet found.
starting USB...
Bus usb@7e980000: usb dr_mode not found
USB DWC2
scanning bus usb@7e980000 for devices...
Warning: smsc95xx_eth (eth0) using random MAC address - 16:d1:56:63:74:ef
4 USB Device(s) found
       scanning usb for storage devices... 0 Storage Device(s) found
Hit any key to stop autoboot:  0
U-Boot> mmc info
Device: mmc@7e202000
Manufacturer ID: 3
OEM: 5344
Name: SC32G
Bus Speed: 50000000
Mode: SD High Speed (50MHz)
Rd Block Len: 512
SD version 3.0
High Capacity: Yes
Capacity: 29.7 GiB
Bus Width: 4-bit
Erase Group Size: 512 Bytes

So on newer firmware bcm2835_get_mmc_clock
https://source.denx.de/u-boot/u-boot/-/blob/v2021.07/arch/arm/mach-bcm283x/msg.c#L74

is returning 0 for clock BCM2835_MBOX_CLOCK_ID_CORE (4)

[jlinton]

Ok, reproduced it fully with a rpi4-8G model in edk2.

When it works (with a newer sd card)

...
RpiFirmwareSetClockState: Request clock state C = 1
RpiFirmwareSetClockState: Request clock state 1 = 1
...
RpiFirmwareGetClockRate: Get Clock Rate: Tag=30002 ClockId=C
RpiFirmwareGetClockRate: Get Clock Rate (MailboxBuf=F5A5F000):
20 00 00 00 00 00 00 00
02 00 03 00 08 00 00 00
00 00 00 00 0C 00 00 00
00 00 00 00 00 00 00 00
RpiFirmwareGetClockRate: Get Clock Rate Done:
20 00 00 00 00 00 00 80
02 00 03 00 08 00 00 00
08 00 00 80 0C 00 00 00
00 E1 F5 05 00 00 00 00
RpiFirmwareGetClockRate: Get Clock Rate return: ClockRate=100000000

But that last bit when it fails:

RpiFirmwareGetClockRate: Get Clock Rate: Tag=30002 ClockId=C
RpiFirmwareGetClockRate: Get Clock Rate (MailboxBuf=F5A5F000):
20 00 00 00 00 00 00 00
02 00 03 00 08 00 00 00
00 00 00 00 0C 00 00 00
00 00 00 00 00 00 00 00
RpiFirmwareGetClockRate: Get Clock Rate Done:
20 00 00 00 00 00 00 80
02 00 03 00 08 00 00 00
08 00 00 80 0C 00 00 00
00 00 00 00 00 00 00 00
RpiFirmwareGetClockRate: Get Clock Rate return: ClockRate=0

The fedora defect: https://bugzilla.redhat.com/show_bug.cgi?id=1999180

Notes that uboot is splatting:

sdhci_setup_cfg: Hardware doesn't specify base clock frequency

which happens the same way (the mailbox is returning that the clock rate is 0)

but it also notes that its dependent on SD card, which seems to be the case since I spent an hour or so thinking I was crazy because I couldn't get it to trigger today.

Further, its not apparently some kind of powersave/whatever going on because If I issue a request to set the clockrate to 100mhz on the emmc2 right before requesting the current state it will accept the request, but then immediately return that the clockrate is 0.

[jens-maus]

Please note, that I am seeing the same behaviour here with a RaspberryPi2 and the latest 1.20210831 firmware. As soon as I use that version rather than the previous 1.20210805 one the SD card performance within u-boot drops significantly (from ~ 23MB/s to 120KB/s). So it seems that this is not limited to a Pi3 or Pi4 but also affects the older Pi2 as well.

[vfazio]

Is there any further information needed to help with this issue?

[pelwell]

@popcornmix This seems to be a direct consequence of making GET_CLOCK_RATE specify the REQUIRED flag for all but CLOCK_ARM.

[popcornmix]

GET_CLOCK_RATE has always been problematic, as the firmware can change the clocks for a variety of reasons.
e.g. core clock changes after initial_turbo has expired, during hdmi mode sets, when temperature is high, and during expensive gpu operations.
This caused an issue with the linux kernel's use, as sometimes it queried the clock and skipped setting it. That caused hard to reproduce errors when the clock just happened to temporarily match what was wanted, so the request was skipped, and when the firmware removed it's clock requirement the clock no longer matched what was wanted by linux.

The fix for this was to make GET_CLOCK_RATE just return the last value requested by SET_CLOCK_RATE.
The actual clock chosen is the max of all requests (i.e. what the arm has requested, plus requests from the firmware).

If uboot is just using this call to get a fixed clock without setting it, it will now get zero returned.
Note: that this was always unsafe as on different boots you could end up with a different value returned.

It may be better for uboot to call GET_MIN_CLOCK. That should return the value you were previously usually getting before the firmware update. However it will now not be subject to changes based on temperature, initial_turbo, hdmi requirements etc.

The other option is to use GET_CLOCK_MEASURED, which will return the actual value of a clock, but this will include temporary changes based on what firmware is doing, and as it's actually measured, the values have a little jitter on them.

[vfazio]

@popcornmix thanks

I thought @jlinton mentioned that setting the clock and then retrieving it still returned 0... I can try playing around with uboot to see what happens with:

1. setting the rate then retrieving it
2. using GET_MIN_CLOCK
3. using GET_CLOCK_MEASURED

[popcornmix]

I'd expect setting clock and retrieving it to give the value you set. Let me now if you can confirm that.

[jlinton]

MIN clock, or MAX clock? I think in both uboot/edk2 the returned clock rate is being used to select the smallest possible divisor for the given card (aka run it as fast as possible). I don't think either of those project is really interested in a dynamic clock value, but rather its peak. If the actual clock rate is lower, AFAIK SD cards should be able to deal with that. The problem is if it ends up going over the card max.

[popcornmix]

MAX clock may be safer if you don't want a divided down value to exceed a specced value.