Pi4 SPI clock running at half speed or is mainline at double speed?

[notro]

Describe the bug

I'm testing SPI display drivers in rpi-linux and have discovered that here they run at half speed compared to mainline. I've done lots of testing over the years so I can't imagine it was like this some years back without me noticing it. I haven't looked at performance numbers for these displays in a long time so I can't remember what it's supposed to be, but I assume mainline is correct.

Doubling the SPI speed downstream gives the same result as in mainline. I haven't got a scope so I can't look at the clock, but I have a display and can see when the clock runs too fast resulting in garbled pixels and the doubling fits this.

Steps to reproduce the behaviour

trace output showing a ~64MHz pixel transfer including setting the controller RAM window. The buffer transfer is split into 3 DMA transfers by spi-bcm2835. This is just to give some background on the transfers:

Linux pi4 5.10.92-v7l+ #1514 SMP Mon Jan 17 17:38:03 GMT 2022 armv7l

$ sudo trace-cmd start -e spi:spi_transfer_start

pi@pi4:~ $ modetest -M mi0283qt -s 31:320x240 -v
setting mode 320x240-0.01Hz on connectors 31, crtc 34
failed to set gamma: Function not implemented
freq: 19.43Hz
freq: 19.35Hz

$ sudo trace-cmd show

    kworker/u8:0-1371    [001] .... 56488.437992: spi_transfer_start: spi0.0 6a13c37b len=1 tx=[2a] rx=[]
    kworker/u8:0-1371    [001] .... 56488.438062: spi_transfer_start: spi0.0 6a13c37b len=4 tx=[00-00-01-3f] rx=[]
    kworker/u8:0-1371    [001] .... 56488.438137: spi_transfer_start: spi0.0 6a13c37b len=1 tx=[2b] rx=[]
    kworker/u8:0-1371    [001] .... 56488.438203: spi_transfer_start: spi0.0 6a13c37b len=4 tx=[00-00-00-ef] rx=[]
    kworker/u8:0-1371    [001] .... 56488.438277: spi_transfer_start: spi0.0 1c3c9519 len=1 tx=[2c] rx=[]
    kworker/u8:0-1371    [001] .... 56488.438456: spi_transfer_start: spi0.0 2a1b0fd1 len=65532 tx=[...] rx=[]
    kworker/u8:0-1371    [001] .... 56488.459568: spi_transfer_start: spi0.0 aa8fc3e1 len=65532 tx=[...] rx=[]
    kworker/u8:0-1371    [001] .... 56488.480712: spi_transfer_start: spi0.0 14c13493 len=22536 tx=[...] rx=[]
<added newline to separate framebuffer updates>
    kworker/u8:0-1371    [001] .... 56488.489781: spi_transfer_start: spi0.0 6a13c37b len=1 tx=[2a] rx=[]
    kworker/u8:0-1371    [001] .... 56488.489868: spi_transfer_start: spi0.0 6a13c37b len=4 tx=[00-00-01-3f] rx=[]
    kworker/u8:0-1371    [001] .... 56488.489948: spi_transfer_start: spi0.0 6a13c37b len=1 tx=[2b] rx=[]
    kworker/u8:0-1371    [001] .... 56488.490021: spi_transfer_start: spi0.0 6a13c37b len=4 tx=[00-00-00-ef] rx=[]
    kworker/u8:0-1371    [001] .... 56488.490109: spi_transfer_start: spi0.0 1c3c9519 len=1 tx=[2c] rx=[]
    kworker/u8:0-1371    [001] .... 56488.490297: spi_transfer_start: spi0.0 2a1b0fd1 len=65532 tx=[...] rx=[]
    kworker/u8:0-1371    [001] .... 56488.511485: spi_transfer_start: spi0.0 aa8fc3e1 len=65532 tx=[...] rx=[]
    kworker/u8:0-1371    [001] .... 56488.532647: spi_transfer_start: spi0.0 14c13493 len=22536 tx=[...] rx=[]

Refs:

• modetest run with -v flips 2 buffers continuously.
• Flushing function: mipi_dbi_fb_dirty()
• SPI transfer function for this display: mipi_dbi_typec3_command()

As a comparison a theoretical 62.5MHz SPI 320x240-RGB565 buffer throughput is: 62500000 / (320 * 240 * 2 * 8) = 50 fps (without the RAM windowing commands ofc).

Mainline (drm-misc-next) spi-max-frequency=64MHz

pi@pi4:~ $ uname -a
Linux pi4 5.17.0-rc2+ #1 SMP Mon Feb 28 12:49:23 CET 2022 armv7l GNU/Linux

# an overlay I use to enable SPI with DMA in mainline
dtoverlay=spi0-2cs-mainline

pi@pi4:~ $ modetest -M mi0283qt -s 31:320x240 -v
setting mode 320x240-0.01Hz on connectors 31, crtc 34
failed to set gamma: Function not implemented
freq: 44.78Hz
freq: 44.58Hz

# added instrumentation in bcm2835_spi_transfer_one(),
# MIPI DCS RAM commands @10MHz and pix transfer @64MHz:
[   54.037358] spi_hz=10000000 cdiv=50 effective_speed_hz=9999999 bs->clk_hz=499999998
[   54.037555] spi_hz=10000000 cdiv=50 effective_speed_hz=9999999 bs->clk_hz=499999998
[   54.037755] spi_hz=10000000 cdiv=50 effective_speed_hz=9999999 bs->clk_hz=499999998
[   54.037942] spi_hz=10000000 cdiv=50 effective_speed_hz=9999999 bs->clk_hz=499999998
[   54.038137] spi_hz=10000000 cdiv=50 effective_speed_hz=9999999 bs->clk_hz=499999998
[   54.038416] spi_hz=64000000 cdiv=8 effective_speed_hz=62499999 bs->clk_hz=499999998
[   54.047240] spi_hz=64000000 cdiv=8 effective_speed_hz=62499999 bs->clk_hz=499999998
[   54.055809] spi_hz=64000000 cdiv=8 effective_speed_hz=62499999 bs->clk_hz=499999998

Downstream spi-max-frequency=64MHz

pi@pi4:~ $ uname -a
Linux pi4 5.15.25-v7l+ #1 SMP Wed Mar 2 18:27:56 CET 2022 armv7l GNU/Linux

pi@pi4:~ $ modetest -M mi0283qt -s 31:320x240 -v
setting mode 320x240-0.01Hz on connectors 31, crtc 34
failed to set gamma: Function not implemented
freq: 20.02Hz
freq: 20.79Hz

# same instrumentation:
[   41.137349] spi_hz=10000000 cdiv=50 effective_speed_hz=10000000 bs->clk_hz=500000000
[   41.137416] spi_hz=10000000 cdiv=50 effective_speed_hz=10000000 bs->clk_hz=500000000
[   41.137484] spi_hz=10000000 cdiv=50 effective_speed_hz=10000000 bs->clk_hz=500000000
[   41.137542] spi_hz=10000000 cdiv=50 effective_speed_hz=10000000 bs->clk_hz=500000000
[   41.137609] spi_hz=10000000 cdiv=50 effective_speed_hz=10000000 bs->clk_hz=500000000
[   41.137789] spi_hz=64000000 cdiv=8 effective_speed_hz=62500000 bs->clk_hz=500000000
[   41.158876] spi_hz=64000000 cdiv=8 effective_speed_hz=62500000 bs->clk_hz=500000000
[   41.179588] spi_hz=64000000 cdiv=8 effective_speed_hz=62500000 bs->clk_hz=500000000

I have a buildroot image based on rpi-5.10.y where a SPI display on Pi Zero was running at almost half fps compared to Pi4 at roughly the same SPI speed. I didn't figure out why, maybe I was seeing the same issue (ref).

I'm at loss here, does this ring any bell? Anybody have a scope to look at the SPI clock?

Device (s)

Raspberry Pi 4 Mod. B

System

see above for kernel versions

Logs

No response

Additional context

No response

[pelwell]

The SPI clocks are subdivided from the VPU core clock, which can lead to speed variations. Does setting force_turbo=1 improve the frame rate?

[notro]

Thanks Phil that worked, I'm getting rusty.

spi-bcm2835 reads the clock only at probe time, so I tried to do a clk_get_rate() in bcm2835_spi_transfer_one() instead of using the cached bs->clk_hz, but it gave the same result.
Is the GPU controlling the clock and Linux doesn't know about it?

[notro]

There is already an issue for this #3381