SPI driver seems to hang at high clock frequencies

[mkeeter]

When testing SPI at a DIV2 clock divider (50 MHz, see https://github.com/oxidecomputer/hardware-cosmo/issues/766#issuecomment-3050259583), we noticed what looks like a hang in the SPI driver. Normally, cosmo_seq takes a tiny amount of time to configure FPGA2 over SPI3, but in this test it never finished:

➜  hubris git:(master) ✗ humility tasks
humility: attached via ST-Link V3
system time = 43495
ID TASK                       GEN PRI STATE
 0 jefe                         0   0 recv, notif: fault timer(T+5)
 1 net                          0   5 notif: jefe-state-change
 2 sys                          0   1 recv, notif: exti-wildcard-irq(irq6/irq7/irq8/irq9/irq10/irq23/irq40)
 3 spi2_driver                  0   3 recv
 4 spi3_driver                  0   3 notif: spi-irq(irq51)
 5 i2c_driver                   0   3 recv
 6 packrat                      0   1 recv
 7 thermal                      0   8 wait: send to cosmo_seq/gen0
 8 power                        0   8 wait: send to cosmo_seq/gen0
 9 hiffy                        0   7 notif: bit31(T+15)
10 cosmo_seq                    0   7 wait: reply from spi3_driver/gen0
11 ignition_flash               0   7 recv
12 spartan7_loader              0   4 recv
13 hash_driver                  0   2 recv
14 hf                           0   6 recv, notif: timer
15 update_server                0   3 recv
16 sensor                       0   4 recv
17 host_sp_comms                0   9 recv, notif: jefe-state-change usart-irq(irq71) multitimer control-plane-agent
18 udpecho                      0   6 wait: send to net/gen0
19 udpbroadcast                 0   6 wait: send to net/gen0
20 control_plane_agent          0   8 wait: send to net/gen0
21 sprot                        0   4 recv
22 validate                     0   5 recv
23 vpd                          0   4 recv
24 user_leds                    0   2 recv, notif: timer
25 dump_agent                   0   6 wait: send to net/gen0
26 sbrmi                        0   4 recv
27 spd                          0   7 notif: jefe-state-change
28 auxflash                     0   3 recv
29 idle                         0  15 RUNNING
30 udprpc                       0   6 wait: send to net/gen0
31 fmc_demo                     0   6 recv, notif: socket

humility tasks -sl spi3_driver
humility: attached via ST-Link V3
system time = 183694
ID TASK                       GEN PRI STATE
 4 spi3_driver                  0   3 notif: spi-irq(irq51)
   |
   +--->  0x24068290 0x0804c178 userlib::sys_recv_stub
                     @ /hubris/sys/userlib/src/lib.rs:368
          0x24068368 0x0804aa8a userlib::sys_recv
                     @ /hubris/sys/userlib/src/lib.rs:296
          0x24068368 0x0804aa8a userlib::sys_recv_notification
                     @ /hubris/sys/userlib/src/lib.rs:340
          0x24068368 0x0804a8f2 <drv_stm32h7_spi_server::ServerImpl as drv_stm32h7_spi_server::InOrderSpiImpl>::write
                     @ /hubris/drv/stm32h7-spi-server/src/main.rs:73
          0x24068368 0x0804a886 drv_stm32h7_spi_server::<impl idol_runtime::Server<drv_stm32h7_spi_server::SpiOperation> for (core::marker::PhantomData<drv_stm32h7_spi_server::SpiOperation>,&mut S)>::handle
                     @ /hubris/target/thumbv7em-none-eabihf/release/build/drv-stm32h7-spi-server-d0f0d84fec042ad1/out/server_stub.rs:243
          0x24068368 0x0804a63e idol_runtime::dispatch
                     @ /git/idolatry-1ebf1c2fd2f30300/6c54f3b/runtime/src/lib.rs:228
          0x24068368 0x0804aa9a main
                     @ /hubris/drv/stm32h7-spi-server/src/main.rs:33

[mkeeter]

I reproduced this on a Grapefruit by changing the FPGA clock divider to DIV4, but am puzzled as to what's going on.

Here's a relevant chunk of the spi2_driver ringbuf:

  17  359       15        1 Start(write, (0xa8, 0x0))
  18  469       15        8 Tx(0xff)
  19  533       15        1 WaitISR(0xa02007)
  20  503       15        1 Rx(0x0)
  21  469       15        1 Tx(0xff)
  22  533       15        1 WaitISR(0xa00002)
  23  533       15        1 WaitISR(0x9f0002)

This isn't a case of a missed interrupt on the Hubris side, manually reading from the status register gives the same result:

$ humility readmem 0x40003814 -w 4
humility: attached via ST-Link V3
                    0       \/        8        c
0x40003810 |          009f0002                   |     ....

Unpacking the bits of the status register:

• CTSIZE is 0x9f, which makes sense: we started sending 0xa8 bytes, and have sent 9 so far
• The only other bit set is TXP, telling us there's room in the TX FIFO

The weird part here is that we don't see any data in the RX FIFO: neither RXWNE nor RXP are set. This doesn't make sense; SPI is synchronous, so we should see as many frames as we've sent.

I can manually write to the data register from Humility. Each time I do, the CTSIZE goes down by 4 (because I'm using writeword). After writing a word, sometimes the system gets unstuck and reads another byte.

Here's what that looks like:

  18  359       15        1 Start(write, (0xa8, 0x0))
  19  469       15        8 Tx(0xff)
  20  533       15        1 WaitISR(0xa02007)
  21  503       15        1 Rx(0x0)
  22  469       15        1 Tx(0xff)
  23  533       15        1 WaitISR(0xa00002)
  24  533       15        1 WaitISR(0x9f0002)
  [humility writeword 0x40003820 0x12345678, called 7 times]
  25  503       15        1 Rx(0x7f) # we receive a single byte (??)
  26  469       15        1 Tx(0xff)
  27  533       15        1 WaitISR(0x830002)
  28  533       15        1 WaitISR(0x820002)

The question now is why aren't the SPI RX FIFO flags being set?

I don't see anything about this in the errata or the forums.

[mkeeter]

I did an experiment where I halted the spi2_driver task, then manually wrote to the TXDR register with

humility writeword 0x40003820 0x12345678

(note that each write causes the CTSIZE to go down by 4, because the register is sensitive to the write width)

Every eight writes (32 bytes) to the data register causes the RXP flag to be set. Reading that value back with

humility readmem 0x40003830 -w 4

returns 0xFF and clears the flags.

If I instead perform 16 writes to the data register, I get back 0xFFFF. It sure seems like the SPI peripheral is only clocking in one bit per write, which is... very odd.