select.poll() / socket.readinto() dropping UDP packets?

[ghfbsd]

Dear Experts -

My program (relevant piece listed below) runs on a RPi pico. It is a WiFi hub passing UDP packets from a control computer to a device on a CAN bus and passing responses from the device out back over WiFi to the control computer. The problem is that it is dropping UDP packets that arrive in a particular sequence.

I have traced the packets sent from the control computer using tcpdump so know that the packets were transmitted and their timing / latency. There is tracing code in the UDP packet receiver code that dumps the packets as they are received. There is also timing code in the packet receiver to check the timing of the main loop (it uses nonblocking select.poll() to check for incoming packets) and also timing code to monitor time spent outside of the UDP polling loop.

I know what packets are lost because I see them sent in the tcpdump log but not received in the UDP packet receiver log. All packets are the same size (CS2_SIZE, which is 13 bytes - not big). The log shows that packets are sent by the control computer every ~13 ms. The mean response time in the polling loop is 1.7 ms and max response time is 2.2 ms. The mean time outside of the UDP polling loop is 0.7 ms and max time is 0.8 ms. The lost packets are always being sent from the control computer; there are no losses in packets sent from the RPi pico. Consequently, I do not suspect any problems with the wifi network.

On this account I cannot see why I am losing packets. I hesitate to think that there is a problem in MicroPython's select.poll() / socket.recvfrom() / socket.readinto() implementation, but the timings suggest it. I'd welcome alternative suggestions on improving the response or understanding how the packet loss arises.

Signed,
Puzzled Pico Programmer

Code follows; apologies for not being able to provide a runnable test (it would require the control computer originating the packets as well!).

System: MicroPython v1.24.1 on 2024-11-29; Raspberry Pi Pico W with RP2040

CS2_SIZE = const(13)             # Fixed by protocol definition

QSIZE = const(25)                # Size of various I/O queues (overkill)

UDPtoCAN = ThreadSafeQueue(QSIZE*[bytearray(CS2_SIZE)])

rrhash = 0
ctsin, ctsou = array.array('L',10*(0,)), array.array('L',10*(0,))

async def UDP_READER(timeout=0):
   # packet layout:
   #    xx xx xx xx  xx  xx xx xx xx xx xx xx xx  -  13 bytes total = CS2_SIZE
   #    -----------  --  -----------------------
   #       CAN ID    len  data (left justified)
   import uselect as select
   global rrhash, ctsin, ctsou, tsbase

   s = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
   s.setblocking(False)
   s.bind(('0.0.0.0',CS2_RPORT))
   p = select.poll()
   p.register(s, select.POLLIN)
   print('UDP listening, waiting for traffic.')
   cti, cto = 0, 0
   cpkt = []
   for i in range(QSIZE): cpkt.append(bytearray(CS2_SIZE))

   while True:                   # Wait for activity on port
      tin = ticks_us()
      if p.poll(timeout):
         pkt = cpkt[cti % QSIZE]
         n = s.readinto(pkt, CS2_SIZE)
      #  assert n == CS2_SIZE
      #  pkt = s.recvfrom(CS2_SIZE)[0]
      #  n = cti % QSIZE
      #  for i in range(CS2_SIZE): cpkt[n][i] = pkt[i]
      #  pkt = cpkt[n]
         mem = memoryview(pkt)
         rrhash = int.from_bytes(mem[2:4])
         comm = int.from_bytes(mem[0:2]) >> 1 & 0xff
         sub = int(pkt[9])
         desc = '???'
         if comm == 0x04: desc = 'LSP'
         if comm == 0x05: desc = 'LDI'
         if comm == 0x06: desc = 'LFU'
         if comm == 0x18: desc = 'PNG'
         if comm == 0x00 and sub == 0: desc = 'STP'
         if comm == 0x00 and sub == 1: desc = 'SGO'
         if comm == 0x00 and sub == 2: desc = 'SHL'
         if comm == 0x00 and sub == 32: desc = 'CLK'
         dtus = ticks_diff(ticks_us(),tsbase)
         dtss, dtfr = dtus//1000000, dtus%1000000
         print('%4d.%06d < %s %s' % ( dtss, dtfr, desc, pkt.hex() ))
      #  await UDPtoCAN.put(pkt)    # might miss incoming packet here?
      #  await debugQUE.put(pkt)    # might miss incoming packet here?
         UDPtoCAN.put_sync(pkt)     # put_sync because no await used
      #  debugQUE.put_sync(pkt)     # put_sync because no await used
         ctsin[cti%10] = ticks_diff(ticks_us(), tin)
         cti += 1
         continue
      tin = ticks_us()
      await asyncio.sleep_ms(0)
      ctsou[cto%10] = ticks_diff(ticks_us(),tin)
      cto += 1

[peterhinch]

Is it normal practice to use select.poll with a nonblocking socket? I've regarded the two techniques as alternative ways to achieve concurrency.

[ghfbsd]

NB - If I comment out the s.setblocking(False) statement, there is no change in program behaviour: packets received in bursts are still lost.

[ghfbsd]

NB - If I keep s.setblocking(False) and eliminate p.poll() in favor of if n is None: after the readinto(), there is no change in program behaviour either: packets received in bursts are lost. I think that tests each of the alternatives that peterhinch outlines.

[peterhinch]

Much as I promote the use of asyncio, I think your performance requirements exceed its capabilities. To have messages arriving at 13ms intervals is a demanding throughput.

My concern about nonblocking sockets is that they can return partial results: they prioritise immediate return over completeness, so precautions are usually required. However your test results suggest that this isn't the problem.

[glenn20]

select.poll() works the same regardless of the non-blocking setting of the socket (as demonstrated by the OP). It is just often used with nonblocking sockets for io multiplexing.

[glenn20]

Much as I promote the use of asyncio, I think your performance requirements exceed its capabilities. To have messages arriving at 13ms intervals is a demanding throughput.

This application is not really using asyncio for the UDP io, so the latency issues of asyncio should not come into play. It is just calling asyncio.sleep_ms(0) whenever there is no data to read in the loop to ensure it plays nicely with other asyncio tasks. If the data rate is very high, it may hog the scheduler. Also, if timeout is greater than 0, this task will play less fairly with other syncio tasks.

[ghfbsd]

Dear All -

After doing more research on slow wifi on the RPi pico, I learned about power management on the wifi chip. Testing showed that disabling power management improved wifi response by about a factor of three. With that change, the asyncio code works. (It was also a relief to learn that the code timings were correct.)

Signed,
(no longer a) Puzzled Pico Programmer

[ctimmer]

Is the example from the forum (now locked):

wlan.active(True)
wlan.config(pm=0xA11140)

functionally the same as the MP documentation (slightly modified):

wlan.active(True)
wlan.config(pm=wlan.PM_NONE)

I get this value when i display the constant:
PM_NONE: 0x10

Curt

[ghfbsd]

Dear Curt -

I have no idea. I tested with the echo program (listed in the forum post) running on the RPi pico and the packet generator (also listed in the forum post) on the control computer. With no wlan.config(pm=0xA11140) the ping test was slow, around 20 ms. With pm= that hex constant, it was fast, around 4-5 ms. That satisfied me, so I used it in my code. Looking at the documentation later and seeing the symbolic constants (including PM_NONE), I simply shrugged and kept using what I knew that demonstrably worked. If your own tests show something different, consult the experts or the original forum responder!

(no longer a) Puzzled Pico Programmer

[glenn20]

wlan.config(pm=wlan.PM_NONE) ensures that the wifi radio is not turned off at all. Other settings may reduce or increase the radio sleep time from the default, but PM_NONE means the radio is always on. Note that this may mean the module runs hotter and will consume more power.

The last hex digit specifies the power save mode. The other bits specify the dtim and beacon timing intervals to request from the AP (and time to return to sleep after wakeup). If the last digit is 0, it does not matter what the other digits are (except the the second last digit should always be greater than 0). SO, pm=0xA11140 and pm=0x10 and pm=wlan.PM_NONE should all be equivalent.

[ghfbsd]

Thanks for clarifying.