search

oxidecomputer / hubris

A lightweight, memory-protected, message-passing kernel for deeply embedded systems.
Mozilla Public License 2.0
2.95k stars 167 forks source link

`transceivers` task reports QueueFull errors #995

Closed bnaecker closed 1 year ago

bnaecker commented 1 year ago

I'm working on the host-side peer of the transceivers task, which is in this repository. I'm plugging that library into the Barefoot Software Development Environment (BF SDE), the driver framework for the Sidecar Tofino ASIC. The SDE uses that crate to query and control the front IO board QSFP transceiver modules, such as asserting low-power mode etc.

The SDE uses a polling model -- every second, it queries all the modules we've told it about to update their presence, reset status, query their identity, etc. In the Sidecar rev B board, there are 64 such ports, 32 of which are queried through the Hubris transceivers task using the above library. So the network activity here is very bursty. Every second, there are 32 modules being queried, usually with several requests, all basically as fast as possible. (There are several requests because the SDE detects presence, and then tries to read the memory map. Further, we need to read the map ourselves to determine how to access it.)

Here's a snippet of the log of the binary actually using that crate, running the BF SDE code for managing the modules:

...
Dec 31 05:14:37.285 DEBG reading front IO QSFP module 34, len: 1, offset: 2, name: qsfp-ffi
Dec 31 05:14:37.285 DEBG received outgoing request: OutstandingHostRequest { request: HostRpcRequest { message: Message { header: Header { version: 2, message_id: 1179 }, modules: ModuleId { fpga_id: 0, ports: PortMask(2) }, body: HostRequest(Read(MemoryRead { page: Sff8636(Lower), offset: 0, len: 1 })) }, data: None }, n_retries: 0, response_tx: Sender { inner: Some(Inner { state: State { is_complete: false, is_closed: false, is_rx_task_set: true, is_tx_task_set: false } }) } }, task: io, name: transceiver-controller
Dec 31 05:14:37.285 DEBG sent outgoing request, message: Message { header: Header { version: 2, message_id: 1179 }, modules: ModuleId { fpga_id: 0, ports: PortMask(2) }, body: HostRequest(Read(MemoryRead { page: Sff8636(Lower), offset: 0, len: 1 })) }, peer: [ff02::1de:2%2]:11112, task: io, name: transceiver-controller
Dec 31 05:14:37.287 DEBG packet received, peer: [fe80::c1d:15ff:fe70:3dbb%2]:11112, n_bytes: 19, task: io, name: transceiver-controller
Dec 31 05:14:37.287 DEBG message from peer, message: Message { header: Header { version: 2, message_id: 1179 }, modules: ModuleId { fpga_id: 0, ports: PortMask(2) }, body: SpResponse(Read(MemoryRead { page: Sff8636(Lower), offset: 0, len: 1 })) }, peer: [fe80::c1d:15ff:fe70:3dbb%2]:11112, task: io, name: transceiver-controller
Dec 31 05:14:37.287 DEBG received outgoing request: OutstandingHostRequest { request: HostRpcRequest { message: Message { header: Header { version: 2, message_id: 1180 }, modules: ModuleId { fpga_id: 0, ports: PortMask(2) }, body: HostRequest(Read(MemoryRead { page: Sff8636(Lower), offset: 0, len: 1 })) }, data: None }, n_retries: 0, response_tx: Sender { inner: Some(Inner { state: State { is_complete: false, is_closed: false, is_rx_task_set: true, is_tx_task_set: false } }) } }, task: io, name: transceiver-controller
Dec 31 05:14:37.287 DEBG sent outgoing request, message: Message { header: Header { version: 2, message_id: 1180 }, modules: ModuleId { fpga_id: 0, ports: PortMask(2) }, body: HostRequest(Read(MemoryRead { page: Sff8636(Lower), offset: 0, len: 1 })) }, peer: [ff02::1de:2%2]:11112, task: io, name: transceiver-controller
Dec 31 05:14:37.289 DEBG packet received, peer: [fe80::c1d:15ff:fe70:3dbb%2]:11112, n_bytes: 19, task: io, name: transceiver-controller
Dec 31 05:14:37.289 DEBG message from peer, message: Message { header: Header { version: 2, message_id: 1180 }, modules: ModuleId { fpga_id: 0, ports: PortMask(2) }, body: SpResponse(Read(MemoryRead { page: Sff8636(Lower), offset: 0, len: 1 })) }, peer: [fe80::c1d:15ff:fe70:3dbb%2]:11112, task: io, name: transceiver-controller
...

It's important to note that these request are all serialized in the library itself. There's only one controller object in the process, and it only allows a single outstanding request at a time. Once the response for that has been received, it starts processing the next one.

At some point I started looking at the ringbuf for the transceivers task, and saw a lot of QueueFull errors:

ben@niles ~ $ pfexec humility --archive /home/aaron/build-sidecar-b.zip --target sidecar-b ringbuf transceivers
humility: WARNING: archive on command-line overriding archive in environment file
humility: attached to 0483:3754:002600184D4B500E20373831 via ST-Link V3
humility: ring buffer drv_transceivers_server::__RINGBUF in transceivers:
 NDX LINE      GEN    COUNT PAYLOAD
   0  332        1        1 FrontIOReady(true)
   1  365        1        1 LEDInit
   2   98        1        1 LEDInitComplete
   3  312        1        1 ModulePresenceUpdate(0xffffffff)
   4  312        1        1 ModulePresenceUpdate(0xfffffffe)
   5  312        1        1 ModulePresenceUpdate(0xffffffff)
   6  312        1        1 ModulePresenceUpdate(0xfffffffe)
   7  312        1        1 ModulePresenceUpdate(0xfffffffc)
   8  312        1        1 ModulePresenceUpdate(0xfffffffd)
   9  312        1        1 ModulePresenceUpdate(0xffffffff)
  10  312        1        1 ModulePresenceUpdate(0xfffffffd)
  11  312        1        1 ModulePresenceUpdate(0xffffffff)
humility: ring buffer drv_transceivers_server::udp::__RINGBUF in transceivers:
 NDX LINE      GEN    COUNT PAYLOAD
   8  250      650        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
   9  152      650        1 SendError(QueueFull)
  10  250      650        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
  11  152      650        1 SendError(QueueFull)
  12  250      650        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
  13  152      650        1 SendError(QueueFull)
  14  250      650        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
  15  152      650        1 SendError(QueueFull)
   0  250      651        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
   1  152      651        1 SendError(QueueFull)
   2  250      651        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
   3  152      651        1 SendError(QueueFull)
   4  250      651        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
   5  152      651        1 SendError(QueueFull)
   6  250      651        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
   7  152      651        1 SendError(QueueFull)

It looks in this case as though the outgoing socket queue is entirely full. I'm not sure how this is possible, for two reasons. First, as I mentioned, the host only sends one request at a time and there's only one controller running on the system. Second, the transceivers task should be just dropping packets it can't send. (That's a normal part of the protocol, the host is responsible for retrying requests.)

At this point, the transceivers task is actually not responding to host requests at all, it really does appear that the queue is full and all packets are dropped. We can see that because the NDX and GEN columns are changing, if we look at the ringbuf output again:

ben@niles ~ $ pfexec humility --archive /home/aaron/build-sidecar-b.zip --target sidecar-b ringbuf transceivers
humility: WARNING: archive on command-line overriding archive in environment file
humility: attached to 0483:3754:002600184D4B500E20373831 via ST-Link V3
humility: ring buffer drv_transceivers_server::__RINGBUF in transceivers:
 NDX LINE      GEN    COUNT PAYLOAD
   0  332        1        1 FrontIOReady(true)
   1  365        1        1 LEDInit
   2   98        1        1 LEDInitComplete
   3  312        1        1 ModulePresenceUpdate(0xffffffff)
   4  312        1        1 ModulePresenceUpdate(0xfffffffe)
   5  312        1        1 ModulePresenceUpdate(0xffffffff)
   6  312        1        1 ModulePresenceUpdate(0xfffffffe)
   7  312        1        1 ModulePresenceUpdate(0xfffffffc)
   8  312        1        1 ModulePresenceUpdate(0xfffffffd)
   9  312        1        1 ModulePresenceUpdate(0xffffffff)
  10  312        1        1 ModulePresenceUpdate(0xfffffffd)
  11  312        1        1 ModulePresenceUpdate(0xffffffff)
humility: ring buffer drv_transceivers_server::udp::__RINGBUF in transceivers:
 NDX LINE      GEN    COUNT PAYLOAD
  14  250      652        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
  15  152      652        1 SendError(QueueFull)
   0  250      653        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
   1  152      653        1 SendError(QueueFull)
   2  250      653        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
   3  152      653        1 SendError(QueueFull)
   4  250      653        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
   5  152      653        1 SendError(QueueFull)
   6  250      653        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
   7  152      653        1 SendError(QueueFull)
   8  250      653        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
   9  152      653        1 SendError(QueueFull)
  10  250      653        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
  11  152      653        1 SendError(QueueFull)
  12  250      653        1 Status(ModuleId { fpga_id: 0x0, ports: PortMask(0xffff) })
  13  152      653        1 SendError(QueueFull)

I've attached a dump I took here.

No tasks appear faulted:

ben@niles ~ $ pfexec humility --archive /home/aaron/build-sidecar-b.zip -t sidecar-b tasks
humility: WARNING: archive on command-line overriding archive in environment file
humility: attached to 0483:3754:002600184D4B500E20373831 via ST-Link V3
system time = 123303521
ID TASK                       GEN PRI STATE
 0 jefe                         0   0 recv, notif: bit0 bit1(T+79)
 1 sys                          0   1 recv
 2 spi1_driver                  0   2 recv
 3 spi2_driver                  0   2 recv
 4 spi3_driver                  0   2 recv
 5 spi4_driver                  0   3 recv
 6 spi5_driver                  0   2 recv
 7 update_server                0   3 recv
 8 auxflash                     0   3 recv
 9 net                         41   5 recv, notif: bit0(irq61) bit2(T+453)
10 control_plane_agent          0   7 recv, notif: bit0 bit1 bit2
11 sprot                        0   4 recv
12 udpecho                      0   6 notif: bit0
13 udpbroadcast                41   6 notif: bit31(T+93)
14 udprpc                       0   6 notif: bit0
15 monorail                     0   6 recv, notif: bit0(T+273)
16 i2c_driver                   0   2 recv
17 hiffy                        0   5 notif: bit31(T+82)
18 sensor                       0   4 recv, notif: bit0(T+480)
19 ecp5_mainboard               0   3 recv
20 ecp5_front_io                0   3 recv
21 transceivers                41   6 recv, notif: bit0 bit1(T+371)
22 sequencer                    0   4 recv, notif: bit0(T+897)
23 thermal                      0   5 recv, notif: bit0(T+916)
24 power                        0   6 notif: bit31(T+381)
25 validate                     0   5 recv
26 ignition                     0   5 recv, notif: bit0(T+897)
27 idle                         0   8 RUNNING

Also note that the system is still running NDP correctly, and responding to pings. This is a snoop capture of the interface that allows communication between the host and SP, while pinging from another shell.

gimlet-c # ./snoop -r -d igb0 'icmp6'
Using device igb0 (promiscuous mode)
fe80::eaea:6aff:fe09:6a7e -> fe80::c1d:dcff:fecf:2734 ICMPv6 Echo request (ID: 35604 Sequence number: 0)
fe80::c1d:dcff:fecf:2734 -> ff02::1:ff09:6a7e ICMPv6 Neighbor solicitation
fe80::eaea:6aff:fe09:6a7e -> fe80::c1d:dcff:fecf:2734 ICMPv6 Neighbor advertisement
fe80::eaea:6aff:fe09:6a7e -> fe80::c1d:dcff:fecf:2734 ICMPv6 Echo request (ID: 35604 Sequence number: 1)
fe80::c1d:dcff:fecf:2734 -> fe80::eaea:6aff:fe09:6a7e ICMPv6 Echo reply (ID: 35604 Sequence number: 1)
fe80::eaea:6aff:fe09:6a7e -> fe80::c1d:dcff:fecf:2734 ICMPv6 Neighbor solicitation
fe80::c1d:dcff:fecf:2734 -> fe80::eaea:6aff:fe09:6a7e ICMPv6 Neighbor advertisement
fe80::20e:c6ff:fe46:43d9 -> ff02::1      ICMPv6 Neighbor advertisement

The link-local ending in 6a7e is the host, and 2734 is the SP. So the host sends a ping, the SP sends an NS to resolve the host's IP, gets a response, and sends the echo reply back to it. So the net task itself doesn't appear borked. Indeed it's ringbuf appears "minimal" (quoting @mkeeter!):

ben@niles ~ $ pfexec humility --archive /home/aaron/build-sidecar-b.zip -t sidecar-b ringbuf net
humility: WARNING: archive on command-line overriding archive in environment file
humility: attached to 0483:3754:002600184D4B500E20373831 via ST-Link V3
humility: ring buffer ksz8463::__RINGBUF in net:
 NDX LINE      GEN    COUNT PAYLOAD
   1  134       11        1 Read(IADR3, 0x420)
   2  134       11        1 Read(IADR2, 0xe1d)
   3  134       11        1 Read(IADR5, 0xdccf)
   4  134       11        1 Read(IADR4, 0x2734)
   5  148       11        1 Write(IACR, 0x1803)
   6  134       11        1 Read(IADR1, 0x0)
   7  134       11        1 Read(IADR3, 0x400)
   8  134       11        1 Read(IADR2, 0xe8ea)
   9  134       11        1 Read(IADR5, 0x6a09)
  10  134       11        1 Read(IADR4, 0x6a7e)
  11  148       11        1 Write(IACR, 0x1804)
  12  134       11        1 Read(IADR1, 0x0)
  13  134       11        1 Read(IADR3, 0x421)
  14  134       11        1 Read(IADR2, 0xe1d)
  15  134       11        1 Read(IADR5, 0xdccf)
   0  134       12        1 Read(IADR4, 0x2735)
humility: ring buffer task_net::mgmt::__RINGBUF in net:
humility: ring buffer vsc85xx::__RINGBUF in net:
 NDX LINE      GEN    COUNT PAYLOAD
   0   26        1        1 Vsc8562InitSgmii(0x0)
   1   23        1        1 ViperPatch(0x0)
   2  133        1        1 GotCrc(0xe194)
   3  133        1        1 GotCrc(0xfb48)

Note

I should note that I first noticed the QueueFull errors earlier this evening, but had to run before I could write this up. At that time, I saw similar errors, but the task appeared to still be responding. That's actually where the noisy log output at the beginning of this issue came from. I have another dump from that state here.

CC @mkeeter

mkeeter commented 1 year ago

I suspect this is https://github.com/smoltcp-rs/smoltcp/issues/713 ; I'm going to fork + fix the smoltcp issue, then we can try a test build which uses that fork.