Pico-W: bad network throughput running as a webserver

[bablokb]

CircuitPython version

at least since 8.0.5

Code/REPL

see https://github.com/bablokb/circuitpython-examples/tree/master/webserver

Behavior

see below

Description

The example scenario runs a webserver. The main page sources a number of js and css-files. This triggers multiple parallel requests from the browser to the server. Total download size is about 140KB, throughputs (measured as total download time from within the browser development tools) are as follows:

• Pico-W (8.0.5 and 9.2.1): about 11s
• Pico Plus2 W: about 11s
• Adafruit Feather ESP32-S3 (4MB/2MB): about 1s

Additional information

This issue is opened on request of @eightycc, see #9826 (comment)

Searching the web for throughput figures for the Pico-W does not turn up many results. Some tests use iperf, but this is an artificial tool and does not test the given scenario. But maybe iperf could help to track down the cause. It seems there is a Python/MicroPython version available, so it might be worth a look.

[bablokb]

See this post: https://forums.raspberrypi.com/viewtopic.php?t=339512

They claim using iperf they see

near 10 Mbits/sec at data size greater than 1 MByte

But this is with the Pico-W running as a client and it is a huge data size for an MCU, so this is not realistic in any way.

[eightycc]

@bablokb Thank you for opening the issue and providing the diagnostic. I was able to easily reproduce the performance glitch.

Capturing a trace with WireShark, I can see that TCP PSH/ACK packets from the server are sometimes delayed by up to 500 ms. Interestingly, the delayed packets always arrive on exact 500 ms offsets from the start of the trace, i.e., +4.620 ms, +5.120 ms, and so on. This tells me that ACKs from the client aren't always causing an IRQ or the IRQ is getting ignored. The reason we're beating at 500 ms is that a periodic timer in CircuitPython (or less likely the CYW43) is causing a poll of pending interrupts to occur.

[bablokb]

I ported iperf to CircuitPython: https://github.com/bablokb/circuitpython-iperf. Might be useful for anybody tweaking network code.

Still needs some polishing and it is currently only tested with a Pico-W. The results reproduce what we already know:

> iperf3 -l 4K -c 192.xxx.x.xxx
Connecting to host 192.xxx.x.xxx, port 5201
[  5] local 192.xxx.x.xxx port 35514 connected to 192.xxx.x.xxx port 5201
[ ID] Interval           Transfer     Bitrate         Retr  Cwnd
[  5]   0.00-1.00   sec   792 KBytes  6.49 Mbits/sec    0   27.1 KBytes       
[  5]   1.00-2.00   sec   600 KBytes  4.91 Mbits/sec    0   27.1 KBytes       
[  5]   2.00-3.00   sec   640 KBytes  5.24 Mbits/sec    0   27.1 KBytes       
[  5]   3.00-4.00   sec   600 KBytes  4.92 Mbits/sec    0   27.1 KBytes       
[  5]   4.00-5.00   sec   720 KBytes  5.90 Mbits/sec    0   27.1 KBytes       
[  5]   5.00-6.00   sec   680 KBytes  5.57 Mbits/sec    0   27.1 KBytes       
[  5]   6.00-7.00   sec   640 KBytes  5.24 Mbits/sec    0   27.1 KBytes       
[  5]   7.00-8.00   sec   680 KBytes  5.57 Mbits/sec    0   27.1 KBytes       
[  5]   8.00-9.00   sec   600 KBytes  4.92 Mbits/sec    0   27.1 KBytes       
[  5]   9.00-10.00  sec   680 KBytes  5.57 Mbits/sec    0   27.1 KBytes       
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bitrate         Retr
[  5]   0.00-10.00  sec  6.48 MBytes  5.43 Mbits/sec    0   sender
[  5]   0.00-10.41  sec  6.38 MBytes  5.14 Mbits/sec        receiver

iperf Done.

> iperf3 -l 4K -R -c 192.xxx.x.xxx
Connecting to host 192.xxx.x.xxx, port 5201
Reverse mode, remote host 192.xxx.x.xxx is sending
[  5] local 192.xxx.x.xxx port 57898 connected to 192.xxx.x.xxx port 5201
[ ID] Interval           Transfer     Bitrate
[  5]   0.00-1.02   sec  60.0 KBytes   483 Kbits/sec                  
[  5]   1.02-2.01   sec  52.0 KBytes   432 Kbits/sec                  
[  5]   2.01-3.04   sec  52.0 KBytes   411 Kbits/sec                  
[  5]   3.04-4.03   sec  52.0 KBytes   433 Kbits/sec                  
[  5]   4.03-5.01   sec  52.0 KBytes   433 Kbits/sec                  
[  5]   5.01-6.01   sec  52.0 KBytes   426 Kbits/sec                  
[  5]   6.01-7.09   sec  56.0 KBytes   425 Kbits/sec                  
[  5]   7.09-8.01   sec  48.0 KBytes   426 Kbits/sec                  
[  5]   8.01-9.12   sec  36.0 KBytes   267 Kbits/sec                  
[  5]   9.12-10.19  sec  32.0 KBytes   244 Kbits/sec                  
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bitrate         Retr
[  5]   0.00-10.47  sec   498 KBytes   389 Kbits/sec    0   sender
[  5]   0.00-10.19  sec   492 KBytes   396 Kbits/sec        receiver

iperf Done.

The first run is my laptop sending data, the second run (with the -R i.e. reverse mode option) the Pico-W is sending and the laptop is the receiver.

[eightycc]

The version of LWIP used by RP2 builds hangs up internally when it thinks its statically allocated pcb pool or pbuf pool is exhausted. The hang-up manifests itself as a memory error returned by tcp_write. Socket code in CP waits 50 ms and then retries the write. This retry/fail condition persists until LWIP's tcp_slowtmr fires and LWIP clears whatever internal condition made it think a pool was exhausted and continues operating normally for a few frames. tcp_slowtmr is a 500 ms periodic timer, so that's why the Wireshark trace captures show that heartbeat.

Increasing the size of the pcb and pbuf pools cuts the frequency of the hang-up but does not eliminate it. With both pool sizes increased the time required to serve the webpage in the original report drops from 11 seconds to 2.5 seconds.

Two things need to be done: (1) Tune static memory allocations for LWIP and (2) hunt down the cause of spurious pool full conditions in LWIP and the subsequent hang-ups. The situation is complicated by CP using a locally-modified version of LWIP that is 2 years and 135 commits behind the main line.

As a next step, I'm going to rebase the local changes and then hunt down any remaining problems in LWIP related to this issue.

[eightycc]

#7657 may be related.

[eightycc]

Re-based local modifications to the top of LWIP's main line. Performance problems still persist. Preliminary list of bugs in LWIP affecting CP:

• When a connection is first established on a TCP socket, scrambled code in tcp_input erroneously detects an application rejection of the first frame. This is due to bad arguments sent via the macro TCP_EVENT_RECV. The result is a delayed ACK, sometimes delayed by several hundred milliseconds. Eventually LWIP will deliver the frame and send the ACK, but by then the client may have re-sent the un-ACKed frame. Eventually things smooth out, but at the cost of hundreds of milliseconds. Rinse and repeat for every new connection.
• LWIP is configured to use a pool of statically allocated pbufs. However, tracing shows that it is allocating pbufs out of its own tiny heap. As network activity occurs, LWIP's heap becomes fragmented leading to "memory errors". Handling of these errors leads to delays and network performance degrades as an app runs.

[eightycc]

When a transmission is sent to a TCP socket that is smaller than the TX buffer fill level required to trigger transmission, it will linger in the buffer until a timeout occurs. This imposes a performance penalty on small transmissions and possibly also on the final part of a larger transmission. I'm thinking that this is necessary to avoid sending small fragments to LWIP, but perhaps it can be better tuned by looking at time since last fill in addition to TX fill level.

[eightycc]

Here is a trace showing the first LWIP bug described above.

Client (192.168.1.217:42582) sends a SYN packet to begin 3-way TCP handshake:

37.179.473(00.047.302): cyw43_ll_process_packets 37.179.504(00.000.031): cyw43_read_reg_u16 BUS_FUNCTION 0x4=0xbe2020 37.179.565(00.000.061): cyw43_write_reg_u16 BUS_FUNCTION 0x4=0x2020 37.179.595(00.000.030): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x20928 37.179.626(00.000.031): bus_gspi_status 0x20928 0x104 37.179.656(00.000.030): cyw43_read_bytes 2 0x0 260 37.179.718(00.000.062): [ 74359] ETHRX itf=w0 len=74 src=00:1b:21:f0:77:ee dst=28:cd:c1:ff:bf:1d subtype=0800 37.179.870(00.000.152): IPv4 tlen=60 id=7479 flags=2 frag_offset=0 protocol=6 src=192.168.001.217 dst=192.168.001.230 37.179.901(00.000.031): TCP src=42582 dst=80 seq=4dacf889 ack=00000000 flags=a002 37.179.931(00.000.030): 0x0000: 28cdc1ff bf1d001b 21f077ee 08004500 : 003c1d37 40004006 9875c0a8 01d9c0a8 : (.......!.w...E. .<.7@.@..u...... 37.180.023(00.000.092): 0x0020: 01e6a656 00504dac f8890000 0000a002 : faf0555d 00000204 05b40402 080ae1fc : ...V.PM......... ..U]............ 37.180.145(00.000.122): 0x0040: a3c80000 00000103 0307 : .......... 37.180.206(00.000.061): pbuf_alloc(length=74) 37.180.236(00.000.030): pbuf_alloc(length=74) == 0x20025eec 37.180.267(00.000.031): ethernet_input: dest:28:cd:c1:ff:bf:1d, src:00:1b:21:f0:77:ee, type:800 37.180.297(00.000.030): pbuf_remove_header: old 0x20025efc new 0x20025f0a (14) 37.180.328(00.000.031): ip_input: iphdr->dest 0xe601a8c0 netif->ip_addr 0xe601a8c0 (0x1a8c0, 0x1a8c0, 0xe6000000) 37.180.358(00.000.030): ip4_input: packet accepted on interface w0 37.180.389(00.000.031): ip4_input: 37.180.389(00.000.000): IP header: 37.180.389(00.000.000): +-------------------------------+ 37.180.419(00.000.030): | 4 | 5 | 0x00 | 60 | (v, hl, tos, len) 37.180.450(00.000.031): +-------------------------------+ 37.180.450(00.000.000): | 7479 |010| 0 | (id, flags, offset) 37.180.480(00.000.030): +-------------------------------+ 37.180.480(00.000.000): | 64 | 6 | 0x9875 | (ttl, proto, chksum) 37.180.511(00.000.031): +-------------------------------+ 37.180.511(00.000.000): | 192 | 168 | 1 | 217 | (src) 37.180.541(00.000.030): +-------------------------------+ 37.180.541(00.000.000): | 192 | 168 | 1 | 230 | (dest) 37.180.572(00.000.031): +-------------------------------+ 37.180.572(00.000.000): ip4_input: p->len 60 p->tot_len 60 37.180.603(00.000.031): pbuf_remove_header: old 0x20025f0a new 0x20025f1e (20) 37.180.633(00.000.030): TCP header: 37.180.633(00.000.000): +-------------------------------+ 37.180.664(00.000.031): | 42582 | 80 | (src port, dest port) 37.180.664(00.000.000): +-------------------------------+ 37.180.694(00.000.030): | 1303181449 | (seq no) 37.180.694(00.000.000): +-------------------------------+ 37.180.694(00.000.000): | 0000000000 | (ack no) 37.180.725(00.000.031): +-------------------------------+ 37.180.755(00.000.030): | 10 | |000010| 64240 | (hdrlen, flags (SYN 37.180.786(00.000.031): ), win) 37.180.786(00.000.000): +-------------------------------+ 37.180.786(00.000.000): | 0x555d | 0 | (chksum, urgp) 37.180.816(00.000.030): +-------------------------------+ 37.180.847(00.000.031): pbuf_remove_header: old 0x20025f1e new 0x20025f46 (40) 37.180.877(00.000.030): tcp_input: packed for LISTENing connection. 37.180.908(00.000.031): TCP connection request 42582 -> 80. 37.180.938(00.000.030): tcp_parseopt: MSS 37.180.969(00.000.031): tcp_parseopt: other 37.180.969(00.000.000): tcp_parseopt: other 37.180.969(00.000.000): tcp_parseopt: NOP 37.180.999(00.000.030): tcp_parseopt: other 37.180.999(00.000.000): tcp_enqueue_flags: queuelen: 0 37.181.030(00.000.031): pbuf_alloc(length=4) 37.181.060(00.000.030): pbuf_alloc(length=4) == 0x20028fd8 37.181.091(00.000.031): pbuf_add_header: old 0x20029020 new 0x2002900c (20) 37.181.121(00.000.030): tcp_enqueue_flags: queueing 6510:6511 (0x12) 37.181.152(00.000.031): tcp_enqueue_flags: 1 (after enqueued) 37.181.182(00.000.030): tcp_output: snd_wnd 64240, cwnd 1, wnd 1, effwnd 0, seq 6510, ack 6510 37.181.213(00.000.031): tcp_output: snd_wnd 64240, cwnd 1, wnd 1, effwnd 0, seq 6510, ack 6510, i 0 37.181.243(00.000.030): tcp_output_segment: rtseq 6510 37.181.274(00.000.031): tcp_output_segment: 6510:6510 37.181.304(00.000.030): pbuf_add_header: old 0x2002900c new 0x20028ff8 (20) 37.181.335(00.000.031): ip4_output_if: w00 37.181.335(00.000.000): IP header: 37.181.335(00.000.000): +-------------------------------+ 37.181.365(00.000.030): | 4 | 5 | 0x00 | 44 | (v, hl, tos, len) 37.181.365(00.000.000): +-------------------------------+ 37.181.396(00.000.031): | 10 |000| 0 | (id, flags, offset) 37.181.427(00.000.031): +-------------------------------+ 37.181.427(00.000.000): | 255 | 6 | 0x36b2 | (ttl, proto, chksum) 37.181.457(00.000.030): +-------------------------------+ 37.181.457(00.000.000): | 192 | 168 | 1 | 230 | (src) 37.181.488(00.000.031): +-------------------------------+ 37.181.488(00.000.000): | 192 | 168 | 1 | 217 | (dest) 37.181.518(00.000.030): +-------------------------------+ 37.181.518(00.000.000): ip4_output_if: call netif->output()

Host is about to send SYN/ACK, but since no ARP entry exists for this client it needs to resolve the address first.
Host broadcasts ARP:

37.181.549(00.000.031): etharp_find_entry: found empty entry 1 37.181.549(00.000.000): etharp_find_entry: selecting empty entry 1 37.181.579(00.000.030): etharp_request: sending ARP request. 37.181.610(00.000.031): pbuf_alloc(length=28) 37.181.610(00.000.000): pbuf_alloc(length=28) == 0x2002902c 37.181.640(00.000.030): etharp_raw: sending raw ARP packet. 37.181.671(00.000.031): pbuf_add_header: old 0x2002904c new 0x2002903e (14) 37.181.671(00.000.000): ethernet_output: sending packet 0x2002902c 37.181.701(00.000.030): [ 74363] ETHTX itf=w0 len=42 src=28:cd:c1:ff:bf:1d dst=ff:ff:ff:ff:ff:ff subtype=0806 37.181.823(00.000.122): 0x0000: ffffffff ffff28cd c1ffbf1d 08060001 : 08000604 000128cd c1ffbf1d c0a801e6 : ......(......... ......(......... 37.181.915(00.000.092): 0x0020: 00000000 0000c0a8 01d9 : .......... 37.182.006(00.000.091): cyw43_sdpcm_send_common: kind=2, len=48 37.182.037(00.000.031): cyw43_write_bytes 2 0x0 60 37.182.098(00.000.061): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x28 37.182.189(00.000.091): pbuf_free(0x2002902c) 37.182.220(00.000.031): pbuf_free: deallocating 0x2002902c 37.182.250(00.000.030): etharp_query: queued packet 0x20028fd8 on ARP entry 1 37.182.281(00.000.031): pbuf_free(0x20025eec) 37.182.281(00.000.000): pbuf_free: deallocating 0x20025eec 37.182.342(00.000.061): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x28 37.182.342(00.000.000): bus_gspi_status 0x28 0x0 37.182.373(00.000.031): No packet

Client replies to host ARP packet

37.182.891(00.000.518): cyw43_ll_process_packets 37.182.952(00.000.061): cyw43_read_reg_u16 BUS_FUNCTION 0x4=0xbe2020 37.182.983(00.000.031): cyw43_write_reg_u16 BUS_FUNCTION 0x4=0x2020 37.183.044(00.000.061): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x20528 37.183.044(00.000.000): bus_gspi_status 0x20528 0x102 37.183.074(00.000.030): cyw43_read_bytes 2 0x0 258 37.183.135(00.000.061): [ 74366] ETHRX itf=w0 len=60 src=00:1b:21:f0:77:ee dst=28:cd:c1:ff:bf:1d subtype=0806 37.183.258(00.000.123): 0x0000: 28cdc1ff bf1d001b 21f077ee 08060001 : 08000604 0002001b 21f077ee c0a801d9 : (.......!.w..... ........!.w..... 37.183.349(00.000.091): 0x0020: 28cdc1ff bf1dc0a8 01e60000 00000000 : 00000000 00000000 00000000 : (............... ............ 37.183.441(00.000.092): pbuf_alloc(length=60) 37.183.471(00.000.030): pbuf_alloc(length=60) == 0x20025eec 37.183.502(00.000.031): ethernet_input: dest:28:cd:c1:ff:bf:1d, src:00:1b:21:f0:77:ee, type:806 37.183.532(00.000.030): pbuf_remove_header: old 0x20025efc new 0x20025f0a (14) 37.183.563(00.000.031): etharp_update_arp_entry: 192.168.1.217 - 00:1b:21:f0:77:ee 37.183.624(00.000.061): etharp_find_entry: found matching entry 1 37.183.624(00.000.000): etharp_update_arp_entry: updating stable entry 1

Host sends SYN/ACK to client, step 2 of 3-way TCP handshake:

37.183.654(00.000.030): pbuf_add_header: old 0x20028ff8 new 0x20028fea (14) 37.183.685(00.000.031): ethernet_output: sending packet 0x20028fd8 37.183.685(00.000.000): [ 74367] ETHTX itf=w0 len=58 src=28:cd:c1:ff:bf:1d dst=00:1b:21:f0:77:ee subtype=0800 37.183.776(00.000.091): IPv4 tlen=44 id=10 flags=0 frag_offset=0 protocol=6 src=192.168.001.230 dst=192.168.001.217 37.183.837(00.000.061): TCP src=80 dst=42582 seq=0000196e ack=4dacf88a flags=6012 37.183.837(00.000.000): 0x0000: 001b21f0 77ee28cd c1ffbf1d 08004500 : 002c000a 0000ff06 36b2c0a8 01e6c0a8 : ..!.w.(.......E. .,......6....... 37.183.959(00.000.122): 0x0020: 01d90050 a6560000 196e4dac f88a6012 : 2da0df1a 00000204 05b4 : ...P.V...nM...`. -......... 37.184.051(00.000.092): cyw43_sdpcm_send_common: kind=2, len=64 37.184.082(00.000.031): cyw43_write_bytes 2 0x0 76 37.184.112(00.000.030): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x28 37.184.173(00.000.061): pbuf_free(0x20028fd8) 37.184.173(00.000.000): pbuf_free: 0x20028fd8 has ref 1, ending here. 37.184.204(00.000.031): etharp_input: incoming ARP reply 37.184.234(00.000.030): pbuf_free(0x20025eec) 37.184.234(00.000.000): pbuf_free: deallocating 0x20025eec 37.184.265(00.000.031): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x28 37.184.295(00.000.030): bus_gspi_status 0x28 0x0 37.184.295(00.000.000): No packet

Client replies with an ACK (completing 3-way TCP handshake) plus PSH for 'GET /'

37.186.096(00.001.801): cyw43_ll_process_packets 37.186.157(00.000.061): cyw43_read_reg_u16 BUS_FUNCTION 0x4=0xbe2020 37.186.187(00.000.030): cyw43_write_reg_u16 BUS_FUNCTION 0x4=0x2020 37.186.218(00.000.031): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x20528 37.186.248(00.000.030): bus_gspi_status 0x20528 0x102 37.186.248(00.000.000): cyw43_read_bytes 2 0x0 258 37.186.309(00.000.061): [ 74372] ETHRX itf=w0 len=60 src=00:1b:21:f0:77:ee dst=28:cd:c1:ff:bf:1d subtype=0800 37.186.431(00.000.122): IPv4 tlen=40 id=7480 flags=2 frag_offset=0 protocol=6 src=192.168.001.217 dst=192.168.001.230 37.186.462(00.000.031): TCP src=42582 dst=80 seq=4dacf88a ack=0000196f flags=5010 37.186.523(00.000.061): 0x0000: 28cdc1ff bf1d001b 21f077ee 08004500 : 00281d38 40004006 9888c0a8 01d9c0a8 : (.......!.w...E. .(.8@.@......... 37.186.614(00.000.091): 0x0020: 01e6a656 00504dac f88a0000 196f5010 : faf02987 00000000 00000000 : ...V.PM......oP. ..)......... 37.186.706(00.000.092): pbuf_alloc(length=60) 37.186.737(00.000.031): pbuf_alloc(length=60) == 0x20025eec 37.186.767(00.000.030): ethernet_input: dest:28:cd:c1:ff:bf:1d, src:00:1b:21:f0:77:ee, type:800 37.186.798(00.000.031): pbuf_remove_header: old 0x20025efc new 0x20025f0a (14) 37.186.828(00.000.030): ip_input: iphdr->dest 0xe601a8c0 netif->ip_addr 0xe601a8c0 (0x1a8c0, 0x1a8c0, 0xe6000000) 37.186.859(00.000.031): ip4_input: packet accepted on interface w0 37.186.889(00.000.030): ip4_input: 37.186.889(00.000.000): IP header: 37.186.889(00.000.000): +-------------------------------+ 37.186.920(00.000.031): | 4 | 5 | 0x00 | 40 | (v, hl, tos, len) 37.186.950(00.000.030): +-------------------------------+ 37.186.950(00.000.000): | 7480 |010| 0 | (id, flags, offset) 37.186.981(00.000.031): +-------------------------------+ 37.186.981(00.000.000): | 64 | 6 | 0x9888 | (ttl, proto, chksum) 37.187.011(00.000.030): +-------------------------------+ 37.187.011(00.000.000): | 192 | 168 | 1 | 217 | (src) 37.187.042(00.000.031): +-------------------------------+ 37.187.042(00.000.000): | 192 | 168 | 1 | 230 | (dest) 37.187.072(00.000.030): +-------------------------------+ 37.187.072(00.000.000): ip4_input: p->len 40 p->tot_len 40 37.187.103(00.000.031): pbuf_remove_header: old 0x20025f0a new 0x20025f1e (20) 37.187.133(00.000.030): TCP header: 37.187.133(00.000.000): +-------------------------------+ 37.187.133(00.000.000): | 42582 | 80 | (src port, dest port) 37.187.164(00.000.031): +-------------------------------+ 37.187.164(00.000.000): | 1303181450 | (seq no) 37.187.194(00.000.030): +-------------------------------+ 37.187.194(00.000.000): | 0000006511 | (ack no) 37.187.225(00.000.031): +-------------------------------+ 37.187.225(00.000.000): | 5 | |010000| 64240 | (hdrlen, flags (ACK 37.187.255(00.000.030): ), win) 37.187.255(00.000.000): +-------------------------------+ 37.187.286(00.000.031): | 0x2987 | 0 | (chksum, urgp) 37.187.286(00.000.000): +-------------------------------+ 37.187.316(00.000.030): pbuf_remove_header: old 0x20025f1e new 0x20025f32 (20) 37.187.347(00.000.031): +-+-+-+-+-+-+-+-+-+-+-+-+-+- tcp_input: flags ACK 37.187.377(00.000.030): -+-+-+-+-+-+-+-+-+-+-+-+-+-+ 37.187.377(00.000.000): State: SYN_RCVD 37.187.408(00.000.031): TCP connection established 42582 -> 80. 37.187.438(00.000.030): tcp_receive: window update 64240 37.187.469(00.000.031): tcp_receive: slow start cwnd 2 37.187.469(00.000.000): tcp_receive: ACK for 6511, unacked->seqno 6510:6511 37.187.500(00.000.031): tcp_receive: removing 6510:6511 from pcb->unacked 37.187.530(00.000.030): tcp_receive: queuelen 1 ... pbuf_free(0x20028fd8) 37.187.561(00.000.031): pbuf_free: deallocating 0x20028fd8 37.187.591(00.000.030): 0 (after freeing unacked) 37.187.591(00.000.000): tcp_receive: pcb->rttest 0 rtseq 6510 ackno 6511 37.187.622(00.000.031): tcp_process (SYN_RCVD): cwnd 4380 ssthresh 11680 37.187.683(00.000.061): tcp_output: nothing to send (0x0) 37.187.683(00.000.000): tcp_output: snd_wnd 64240, cwnd 4380, wnd 4380, seg == NULL, ack 6511 37.187.713(00.000.030): State: ESTABLISHED 37.187.713(00.000.000): pbuf_free(0x20025eec) 37.187.744(00.000.031): pbuf_free: deallocating 0x20025eec 37.187.805(00.000.061): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x3b128 37.187.835(00.000.030): bus_gspi_status 0x3b128 0x1d8 37.187.835(00.000.000): cyw43_read_bytes 2 0x0 472 37.187.927(00.000.092): [ 74376] ETHRX itf=w0 len=450 src=00:1b:21:f0:77:ee dst=28:cd:c1:ff:bf:1d subtype=0800 37.188.079(00.000.152): IPv4 tlen=436 id=7481 flags=2 frag_offset=0 protocol=6 src=192.168.001.217 dst=192.168.001.230 37.188.110(00.000.031): TCP src=42582 dst=80 seq=4dacf88a ack=0000196f flags=5018 37.188.140(00.000.030): 0x0000: 28cdc1ff bf1d001b 21f077ee 08004500 : 01b41d39 40004006 96fbc0a8 01d9c0a8 : (.......!.w...E. ...9@.@......... 37.188.232(00.000.092): 0x0020: 01e6a656 00504dac f88a0000 196f5018 : faf098db 00004745 54202f20 48545450 : ...V.PM......oP. ......GET / HTTP 37.188.354(00.000.122): 0x0040: 2f312e31 0d0a486f 73743a20 3139322e : 3136382e 312e3233 300d0a55 7365722d : /1.1..Host: 192. 168.1.230..User- 37.188.446(00.000.092): 0x0060: 4167656e 743a204d 6f7a696c 6c612f35 : 2e302028 5831313b 204c696e 75782078 : Agent: Mozilla/5 .0 (X11; Linux x 37.188.568(00.000.122): 0x0080: 38365f36 343b2072 763a3133 342e3029 : 20476563 6b6f2f32 30313030 31303120 : 86_64; rv:134.0) Gecko/20100101 37.188.659(00.000.091): 0x00a0: 46697265 666f782f 3133342e 300d0a41 : 63636570 743a2074 6578742f 68746d6c : Firefox/134.0..A ccept: text/html 37.188.751(00.000.092): 0x00c0: 2c617070 6c696361 74696f6e 2f786874 : 6d6c2b78 6d6c2c61 70706c69 63617469 : ,application/xht ml+xml,applicati 37.188.873(00.000.122): 0x00e0: 6f6e2f78 6d6c3b71 3d302e39 2c2a2f2a : 3b713d30 2e380d0a 41636365 70742d4c : on/xml;q=0.9,*/* ;q=0.8..Accept-L 37.188.964(00.000.091): 0x0100: 616e6775 6167653a 20656e2d 55532c65 : 6e3b713d 302e350d 0a416363 6570742d : anguage: en-US,e n;q=0.5..Accept- 37.189.086(00.000.122): 0x0120: 456e636f 64696e67 3a20677a 69702c20 : 6465666c 6174650d 0a444e54 3a20310d : Encoding: gzip, deflate..DNT: 1. 37.189.178(00.000.092): 0x0140: 0a436f6e 6e656374 696f6e3a 206b6565 : 702d616c 6976650d 0a557067 72616465 : .Connection: kee p-alive..Upgrade 37.189.270(00.000.092): 0x0160: 2d496e73 65637572 652d5265 71756573 : 74733a20 310d0a53 65632d47 50433a20 : -Insecure-Reques ts: 1..Sec-GPC: 37.189.392(00.000.122): 0x0180: 310d0a50 72696f72 6974793a 20753d30 : 2c20690d 0a507261 676d613a 206e6f2d : 1..Priority: u=0 , i..Pragma: no- 37.189.483(00.000.091): 0x01a0: 63616368 650d0a43 61636865 2d436f6e : 74726f6c 3a206e6f 2d636163 68650d0a : cache..Cache-Con trol: no-cache.. 37.189.605(00.000.122): 0x01c0: 0d0a : .. 37.189.666(00.000.061): pbuf_alloc(length=450) 37.189.666(00.000.000): pbuf_alloc(length=450) == 0x20025eec 37.189.727(00.000.061): ethernet_input: dest:28:cd:c1:ff:bf:1d, src:00:1b:21:f0:77:ee, type:800 37.189.758(00.000.031): pbuf_remove_header: old 0x20025efc new 0x20025f0a (14) 37.189.788(00.000.030): ip_input: iphdr->dest 0xe601a8c0 netif->ip_addr 0xe601a8c0 (0x1a8c0, 0x1a8c0, 0xe6000000) 37.189.819(00.000.031): ip4_input: packet accepted on interface w0 37.189.849(00.000.030): ip4_input: 37.189.849(00.000.000): IP header: 37.189.849(00.000.000): +-------------------------------+ 37.189.849(00.000.000): | 4 | 5 | 0x00 | 436 | (v, hl, tos, len) 37.189.880(00.000.031): +-------------------------------+ 37.189.910(00.000.030): | 7481 |010| 0 | (id, flags, offset) 37.189.941(00.000.031): +-------------------------------+ 37.189.941(00.000.000): | 64 | 6 | 0x96fb | (ttl, proto, chksum) 37.189.971(00.000.030): +-------------------------------+ 37.189.971(00.000.000): | 192 | 168 | 1 | 217 | (src) 37.189.971(00.000.000): +-------------------------------+ 37.190.002(00.000.031): | 192 | 168 | 1 | 230 | (dest) 37.190.002(00.000.000): +-------------------------------+ 37.190.032(00.000.030): ip4_input: p->len 436 p->tot_len 436 37.190.032(00.000.000): pbuf_remove_header: old 0x20025f0a new 0x20025f1e (20) 37.190.063(00.000.031): TCP header: 37.190.063(00.000.000): +-------------------------------+ 37.190.093(00.000.030): | 42582 | 80 | (src port, dest port) 37.190.093(00.000.000): +-------------------------------+ 37.190.124(00.000.031): | 1303181450 | (seq no) 37.190.124(00.000.000): +-------------------------------+ 37.190.124(00.000.000): | 0000006511 | (ack no) 37.190.155(00.000.031): +-------------------------------+ 37.190.155(00.000.000): | 5 | |011000| 64240 | (hdrlen, flags (PSH ACK 37.190.185(00.000.030): ), win) 37.190.185(00.000.000): +-------------------------------+ 37.190.216(00.000.031): | 0x98db | 0 | (chksum, urgp) 37.190.216(00.000.000): +-------------------------------+ 37.190.246(00.000.030): pbuf_remove_header: old 0x20025f1e new 0x20025f32 (20) 37.190.277(00.000.031): +-+-+-+-+-+-+-+-+-+-+-+-+-+- tcp_input: flags PSH ACK 37.190.307(00.000.030): -+-+-+-+-+-+-+-+-+-+-+-+-+-+ 37.190.307(00.000.000): State: ESTABLISHED 37.190.338(00.000.031): tcp_receive: pcb->rttest 0 rtseq 6510 ackno 6511

Erroneous rejection of packet, ACK and 'GET /' PSH are now delayed:

37.190.399(00.000.061): tcp_input: keep incoming packet, because pcb is "full" 37.190.429(00.000.030): tcp_output: nothing to send (0x0) 37.190.429(00.000.000): tcp_output: snd_wnd 64240, cwnd 4380, wnd 4380, seg == NULL, ack 6511 37.190.460(00.000.031): State: ESTABLISHED 37.190.521(00.000.061): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x28 37.190.551(00.000.030): bus_gspi_status 0x28 0x0 37.190.551(00.000.000): No packet 37.191.650(00.001.099): accepted connection from ('192.168.1.217', 42582)

Unrelated WLAN activity:

37.267.669(00.076.019): cyw43_ll_process_packets 37.267.730(00.000.061): cyw43_read_reg_u16 BUS_FUNCTION 0x4=0xbe2020 37.267.791(00.000.061): cyw43_write_reg_u16 BUS_FUNCTION 0x4=0x2020 37.267.852(00.000.061): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x20728 37.267.883(00.000.031): bus_gspi_status 0x20728 0x103 37.267.883(00.000.000): cyw43_read_bytes 2 0x0 259 37.267.944(00.000.061): [ 74536] ETHRX itf=w0 len=121 src=0c:ea:c9:cd:ba:22 dst=ff:ff:ff:ff:ff:ff subtype=7373 37.268.066(00.000.122): 0x0000: ffffffff ffff0cea c9cdba22 73731211 : 00000043 52b50623 e8b2eb04 ceaa676c : ..........."ss.. ...CR..#......gl 37.268.188(00.000.122): 0x0020: c423e946 541173ee 9227a953 2f76dbf1 : 94d235f5 00000201 8003060c eac9cdba : .#.FT.s..'.S/v.. ..5............. 37.268.280(00.000.092): 0x0040: 22040144 0701011b 01000806 0ceac9cd : ba220901 020e1800 00000000 00000000 : "..D............ .".............. 37.268.371(00.000.091): 0x0060: 00000000 00000000 00000000 00000019 : 08a03948 e4b549d8 48 : ................ ..9H..I.H 37.268.463(00.000.092): pbuf_alloc(length=121) 37.268.493(00.000.030): pbuf_alloc(length=121) == 0x200258f0 37.268.524(00.000.031): ethernet_input: dest:ff:ff:ff:ff:ff:ff, src:0c:ea:c9:cd:ba:22, type:7373 37.268.585(00.000.061): pbuf_free(0x200258f0) 37.268.585(00.000.000): pbuf_free: deallocating 0x200258f0 37.268.615(00.000.030): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x20b28 37.268.646(00.000.031): bus_gspi_status 0x20b28 0x105 37.268.646(00.000.000): cyw43_read_bytes 2 0x0 261 37.268.707(00.000.061): [ 74537] ETHRX itf=w0 len=63 src=90:2b:34:3a:a3:7a dst=ff:ff:ff:ff:ff:ff subtype=0800 37.268.829(00.000.122): IPv4 tlen=49 id=61142 flags=2 frag_offset=0 protocol=17 src=192.168.001.215 dst=192.168.001.255 37.268.859(00.000.030): UDP src=42764 dst=32412 len=29 37.268.890(00.000.031): 0x0000: ffffffff ffff902b 343aa37a 08004500 : 0031eed6 40004011 c6bec0a8 01d7c0a8 : .......+4:.z..E. .1..@.@......... 37.268.981(00.000.091): 0x0020: 01ffa70c 7e9c001d dea54d2d 53454152 : 4348202a 20485454 502f312e 310d0a : ....~.....M-SEAR CH * HTTP/1.1.. 37.269.104(00.000.123): pbuf_alloc(length=63) 37.269.104(00.000.000): pbuf_alloc(length=63) == 0x200258f0 37.269.134(00.000.030): ethernet_input: dest:ff:ff:ff:ff:ff:ff, src:90:2b:34:3a:a3:7a, type:800 37.269.165(00.000.031): pbuf_remove_header: old 0x20025900 new 0x2002590e (14) 37.269.195(00.000.030): ip_input: iphdr->dest 0xff01a8c0 netif->ip_addr 0xe601a8c0 (0x1a8c0, 0x1a8c0, 0xff000000) 37.269.226(00.000.031): ip4_input: packet accepted on interface w0 37.269.256(00.000.030): ip4_input: 37.269.256(00.000.000): IP header: 37.269.256(00.000.000): +-------------------------------+ 37.269.256(00.000.000): | 4 | 5 | 0x00 | 49 | (v, hl, tos, len) 37.269.287(00.000.031): +-------------------------------+ 37.269.317(00.000.030): | 61142 |010| 0 | (id, flags, offset) 37.269.317(00.000.000): +-------------------------------+ 37.269.348(00.000.031): | 64 | 17 | 0xc6be | (ttl, proto, chksum) 37.269.348(00.000.000): +-------------------------------+ 37.269.378(00.000.030): | 192 | 168 | 1 | 215 | (src) 37.269.378(00.000.000): +-------------------------------+ 37.269.409(00.000.031): | 192 | 168 | 1 | 255 | (dest) 37.269.439(00.000.030): +-------------------------------+ 37.269.439(00.000.000): ip4_input: p->len 49 p->tot_len 49 37.269.470(00.000.031): pbuf_remove_header: old 0x2002590e new 0x20025922 (20) 37.269.500(00.000.030): pbuf_free(0x200258f0) 37.269.500(00.000.000): pbuf_free: deallocating 0x200258f0 37.269.561(00.000.061): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x28 37.269.592(00.000.031): bus_gspi_status 0x28 0x0 37.269.592(00.000.000): No packet

After a delay of about 100 ms, client re-sends ACK/PSH packet

37.293.670(00.024.078): cyw43_ll_process_packets 37.293.731(00.000.061): cyw43_read_reg_u16 BUS_FUNCTION 0x4=0xbe2020 37.293.792(00.000.061): cyw43_write_reg_u16 BUS_FUNCTION 0x4=0x2020 37.293.823(00.000.031): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x3b128 37.293.823(00.000.000): bus_gspi_status 0x3b128 0x1d8 37.293.853(00.000.030): cyw43_read_bytes 2 0x0 472 37.293.945(00.000.092): [ 74588] ETHRX itf=w0 len=450 src=00:1b:21:f0:77:ee dst=28:cd:c1:ff:bf:1d subtype=0800 37.294.097(00.000.152): IPv4 tlen=436 id=7482 flags=2 frag_offset=0 protocol=6 src=192.168.001.217 dst=192.168.001.230 37.294.128(00.000.031): TCP src=42582 dst=80 seq=4dacf88a ack=0000196f flags=5018 37.294.158(00.000.030): 0x0000: 28cdc1ff bf1d001b 21f077ee 08004500 : 01b41d3a 40004006 96fac0a8 01d9c0a8 : (.......!.w...E. ...:@.@......... 37.294.250(00.000.092): 0x0020: 01e6a656 00504dac f88a0000 196f5018 : faf098db 00004745 54202f20 48545450 : ...V.PM......oP. ......GET / HTTP 37.294.372(00.000.122): 0x0040: 2f312e31 0d0a486f 73743a20 3139322e : 3136382e 312e3233 300d0a55 7365722d : /1.1..Host: 192. 168.1.230..User- 37.294.464(00.000.092): 0x0060: 4167656e 743a204d 6f7a696c 6c612f35 : 2e302028 5831313b 204c696e 75782078 : Agent: Mozilla/5 .0 (X11; Linux x 37.294.586(00.000.122): 0x0080: 38365f36 343b2072 763a3133 342e3029 : 20476563 6b6f2f32 30313030 31303120 : 86_64; rv:134.0) Gecko/20100101 37.294.677(00.000.091): 0x00a0: 46697265 666f782f 3133342e 300d0a41 : 63636570 743a2074 6578742f 68746d6c : Firefox/134.0..A ccept: text/html 37.294.769(00.000.092): 0x00c0: 2c617070 6c696361 74696f6e 2f786874 : 6d6c2b78 6d6c2c61 70706c69 63617469 : ,application/xht ml+xml,applicati 37.294.860(00.000.091): 0x00e0: 6f6e2f78 6d6c3b71 3d302e39 2c2a2f2a : 3b713d30 2e380d0a 41636365 70742d4c : on/xml;q=0.9,*/* ;q=0.8..Accept-L 37.294.982(00.000.122): 0x0100: 616e6775 6167653a 20656e2d 55532c65 : 6e3b713d 302e350d 0a416363 6570742d : anguage: en-US,e n;q=0.5..Accept- 37.295.074(00.000.092): 0x0120: 456e636f 64696e67 3a20677a 69702c20 : 6465666c 6174650d 0a444e54 3a20310d : Encoding: gzip, deflate..DNT: 1. 37.295.196(00.000.122): 0x0140: 0a436f6e 6e656374 696f6e3a 206b6565 : 702d616c 6976650d 0a557067 72616465 : .Connection: kee p-alive..Upgrade 37.295.288(00.000.092): 0x0160: 2d496e73 65637572 652d5265 71756573 : 74733a20 310d0a53 65632d47 50433a20 : -Insecure-Reques ts: 1..Sec-GPC: 37.295.410(00.000.122): 0x0180: 310d0a50 72696f72 6974793a 20753d30 : 2c20690d 0a507261 676d613a 206e6f2d : 1..Priority: u=0 , i..Pragma: no- 37.295.501(00.000.091): 0x01a0: 63616368 650d0a43 61636865 2d436f6e : 74726f6c 3a206e6f 2d636163 68650d0a : cache..Cache-Con trol: no-cache.. 37.295.623(00.000.122): 0x01c0: 0d0a : .. 37.295.684(00.000.061): pbuf_alloc(length=450) 37.295.715(00.000.031): pbuf_alloc(length=450) == 0x200258f0 37.295.745(00.000.030): ethernet_input: dest:28:cd:c1:ff:bf:1d, src:00:1b:21:f0:77:ee, type:800 37.295.776(00.000.031): pbuf_remove_header: old 0x20025900 new 0x2002590e (14) 37.295.837(00.000.061): ip_input: iphdr->dest 0xe601a8c0 netif->ip_addr 0xe601a8c0 (0x1a8c0, 0x1a8c0, 0xe6000000) 37.295.867(00.000.030): ip4_input: packet accepted on interface w0 37.295.898(00.000.031): ip4_input: 37.295.898(00.000.000): IP header: 37.295.898(00.000.000): +-------------------------------+ 37.295.928(00.000.030): | 4 | 5 | 0x00 | 436 | (v, hl, tos, len) 37.295.928(00.000.000): +-------------------------------+ 37.295.959(00.000.031): | 7482 |010| 0 | (id, flags, offset) 37.295.989(00.000.030): +-------------------------------+ 37.295.989(00.000.000): | 64 | 6 | 0x96fa | (ttl, proto, chksum) 37.296.020(00.000.031): +-------------------------------+ 37.296.020(00.000.000): | 192 | 168 | 1 | 217 | (src) 37.296.051(00.000.031): +-------------------------------+ 37.296.051(00.000.000): | 192 | 168 | 1 | 230 | (dest) 37.296.051(00.000.000): +-------------------------------+ 37.296.081(00.000.030): ip4_input: p->len 436 p->tot_len 436 37.296.112(00.000.031): pbuf_remove_header: old 0x2002590e new 0x20025922 (20) 37.296.112(00.000.000): TCP header: 37.296.142(00.000.030): +-------------------------------+ 37.296.142(00.000.000): | 42582 | 80 | (src port, dest port) 37.296.173(00.000.031): +-------------------------------+ 37.296.173(00.000.000): | 1303181450 | (seq no) 37.296.173(00.000.000): +-------------------------------+ 37.296.203(00.000.030): | 0000006511 | (ack no) 37.296.203(00.000.000): +-------------------------------+ 37.296.234(00.000.031): | 5 | |011000| 64240 | (hdrlen, flags (PSH ACK 37.296.264(00.000.030): ), win) 37.296.264(00.000.000): +-------------------------------+ 37.296.264(00.000.000): | 0x98db | 0 | (chksum, urgp) 37.296.295(00.000.031): +-------------------------------+ 37.296.325(00.000.030): pbuf_remove_header: old 0x20025922 new 0x20025936 (20) 37.296.356(00.000.031): +-+-+-+-+-+-+-+-+-+-+-+-+-+- tcp_input: flags PSH ACK 37.296.386(00.000.030): -+-+-+-+-+-+-+-+-+-+-+-+-+-+

LWIP recognizes that it has received a duplicate packet, unloads the "kept" packet and ACKs it

37.296.386(00.000.000): State: ESTABLISHED 37.296.417(00.000.031): tcp_input: notify kept packet 37.296.447(00.000.030): tcp_receive: pcb->rttest 0 rtseq 6510 ackno 6511 37.296.478(00.000.031): tcp_receive: duplicate seqno 1303181450 37.296.508(00.000.030): pbuf_alloc(length=20) 37.296.539(00.000.031): pbuf_alloc(length=20) == 0x20028fd8 37.296.539(00.000.000): tcp_output: sending ACK for 1303181846 37.296.600(00.000.061): pbuf_add_header: old 0x2002900c new 0x20028ff8 (20) 37.296.630(00.000.030): ip4_output_if: w00 37.296.630(00.000.000): IP header: 37.296.630(00.000.000): +-------------------------------+ 37.296.661(00.000.031): | 4 | 5 | 0x00 | 40 | (v, hl, tos, len) 37.296.691(00.000.030): +-------------------------------+ 37.296.691(00.000.000): | 11 |000| 0 | (id, flags, offset) 37.296.722(00.000.031): +-------------------------------+ 37.296.722(00.000.000): | 255 | 6 | 0x36b5 | (ttl, proto, chksum) 37.296.722(00.000.000): +-------------------------------+ 37.296.752(00.000.030): | 192 | 168 | 1 | 230 | (src) 37.296.752(00.000.000): +-------------------------------+ 37.296.783(00.000.031): | 192 | 168 | 1 | 217 | (dest) 37.296.783(00.000.000): +-------------------------------+ 37.296.813(00.000.030): ip4_output_if: call netif->output() 37.296.844(00.000.031): pbuf_add_header: old 0x20028ff8 new 0x20028fea (14) 37.296.875(00.000.031): ethernet_output: sending packet 0x20028fd8 37.296.875(00.000.000): [ 74594] ETHTX itf=w0 len=54 src=28:cd:c1:ff:bf:1d dst=00:1b:21:f0:77:ee subtype=0800 37.296.997(00.000.122): IPv4 tlen=40 id=11 flags=0 frag_offset=0 protocol=6 src=192.168.001.230 dst=192.168.001.217 37.297.058(00.000.061): TCP src=80 dst=42582 seq=0000196f ack=4dacfa16 flags=5010 37.297.058(00.000.000): 0x0000: 001b21f0 77ee28cd c1ffbf1d 08004500 : 0028000b 0000ff06 36b5c0a8 01e6c0a8 : ..!.w.(.......E. .(......6....... 37.297.180(00.000.122): 0x0020: 01d90050 a6560000 196f4dac fa165010 : 2c14f6d7 0000 : ...P.V...oM...P. ,..... 37.297.302(00.000.122): cyw43_sdpcm_send_common: kind=2, len=60 37.297.332(00.000.030): cyw43_write_bytes 2 0x0 72 37.297.393(00.000.061): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x28 37.297.454(00.000.061): pbuf_free(0x20028fd8) 37.297.485(00.000.031): pbuf_free: deallocating 0x20028fd8 37.297.515(00.000.030): tcp_output: nothing to send (0x0) 37.297.546(00.000.031): tcp_output: snd_wnd 64240, cwnd 4380, wnd 4380, seg == NULL, ack 6511 37.297.576(00.000.030): State: ESTABLISHED 37.297.576(00.000.000): pbuf_free(0x200258f0) 37.297.576(00.000.000): pbuf_free: deallocating 0x200258f0 37.297.637(00.000.061): cyw43_read_reg_u32 BUS_FUNCTION 0x8=0x28 37.297.637(00.000.000): bus_gspi_status 0x28 0x0 37.297.668(00.000.031): No packet 37.298.065(00.000.397): pbuf_free(0x20025eec) 37.298.095(00.000.030): pbuf_free: deallocating 0x20025eec 37.298.126(00.000.031): tcp_recved: received 396 bytes, wnd 11680 (0). 37.300.018(00.001.892): received request bytearray(b'GET / HTTP/1.1\r\n') 37.305.999(00.005.981): tcp_slowtmr: processing active pcb 37.306.030(00.000.031): tcp_slowtmr: polling application 37.306.030(00.000.000): tcp_output: nothing to send (0x0) 37.306.060(00.000.030): tcp_output: snd_wnd 64240, cwnd 4380, wnd 4380, seg == NULL, ack 6511

Host sends data requested by 'GET /':

37.324.523(00.018.463): _handle_request for / 37.326.110(00.001.587): response status: 200 37.326.629(00.000.519): sending 2931 bytes 37.330.169(00.003.540): tcp_write(pcb=0x20026e64, data=0x20031620, len=67, apiflags=1) 37.330.200(00.000.031): tcp_write: queuelen: 0 37.330.230(00.000.030): pbuf_alloc(length=1460) 37.330.230(00.000.000): pbuf_alloc(length=1460) == 0x20028fd8 37.330.261(00.000.031): pbuf_add_header: old 0x20029020 new 0x2002900c (20) 37.330.291(00.000.030): tcp_write: queueing 6511:6578 37.330.322(00.000.031): tcp_write: 1 (after enqueued) 37.332.489(00.002.167): tcp_write(pcb=0x20026e64, data=0x20031fa0, len=1024, apiflags=1) 37.332.550(00.000.061): tcp_write: queuelen: 1 37.332.580(00.000.030): tcp_write: 1 (after enqueued) 37.334.350(00.001.770): tcp_write(pcb=0x20026e64, data=0x20031b40, len=1024, apiflags=1) 37.334.381(00.000.031): tcp_write: queuelen: 1 37.334.411(00.000.030): pbuf_alloc(length=1460) 37.334.442(00.000.031): pbuf_alloc(length=1460) == 0x200295dc 37.334.503(00.000.061): pbuf_add_header: old 0x20029624 new 0x20029610 (20) 37.334.533(00.000.030): tcp_write: queueing 7971:8626 37.334.564(00.000.031): tcp_write: 2 (after enqueued) 37.336.334(00.001.770): tcp_write(pcb=0x20026e64, data=0x20031b40, len=883, apiflags=1) 37.336.395(00.000.061): tcp_write: queuelen: 2 37.336.395(00.000.000): pbuf_alloc(length=1460) 37.336.425(00.000.030): pbuf_alloc(length=1460) == 0x20029be0 37.336.456(00.000.031): pbuf_add_header: old 0x20029c28 new 0x20029c14 (20) 37.336.486(00.000.030): tcp_write: queueing 9431:9509 37.336.517(00.000.031): tcp_write: 3 (after enqueued) 37.337.341(00.000.824): tcp_close: closing in State: ESTABLISHED 37.337.371(00.000.030): tcp_output: snd_wnd 64240, cwnd 4380, wnd 4380, effwnd 1460, seq 6511, ack 6511 37.337.432(00.000.061): tcp_output: snd_wnd 64240, cwnd 4380, wnd 4380, effwnd 1460, seq 6511, ack 6511, i 0 37.337.463(00.000.031): tcp_output_segment: rtseq 6511 37.337.463(00.000.000): tcp_output_segment: 6511:7971 37.337.524(00.000.061): pbuf_add_header: old 0x2002900c new 0x20028ff8 (20) 37.337.554(00.000.030): ip4_output_if: w00 37.337.554(00.000.000): IP header: 37.337.554(00.000.000): +-------------------------------+ 37.337.585(00.000.031): | 4 | 5 | 0x00 | 1500 | (v, hl, tos, len) 37.337.585(00.000.000): +-------------------------------+ 37.337.615(00.000.030): | 12 |000| 0 | (id, flags, offset) 37.337.646(00.000.031): +-------------------------------+ 37.337.646(00.000.000): | 255 | 6 | 0x3100 | (ttl, proto, chksum) 37.337.677(00.000.031): +-------------------------------+ 37.337.677(00.000.000): | 192 | 168 | 1 | 230 | (src) 37.337.707(00.000.030): +-------------------------------+ 37.337.707(00.000.000): | 192 | 168 | 1 | 217 | (dest) 37.337.738(00.000.031): +-------------------------------+ 37.337.738(00.000.000): ip4_output_if: call netif->output() 37.337.768(00.000.030): pbuf_add_header: old 0x20028ff8 new 0x20028fea (14) 37.337.768(00.000.000): ethernet_output: sending packet 0x20028fd8 37.337.799(00.000.031): [ 74675] ETHTX itf=w0 len=1514 src=28:cd:c1:ff:bf:1d dst=00:1b:21:f0:77:ee subtype=0800 37.337.951(00.000.152): IPv4 tlen=1500 id=12 flags=0 frag_offset=0 protocol=6 src=192.168.001.230 dst=192.168.001.217 37.337.982(00.000.031): TCP src=80 dst=42582 seq=0000196f ack=4dacfa16 flags=5018 37.338.012(00.000.030): 0x0000: 001b21f0 77ee28cd c1ffbf1d 08004500 : 05dc000c 0000ff06 3100c0a8 01e6c0a8 : ..!.w.(.......E. ........1....... 37.338.104(00.000.092): 0x0020: 01d90050 a6560000 196f4dac fa165018 : 2c14aaa2 00004854 54502f31 2e312032 : ...P.V...oM...P. ,.....HTTP/1.1 2 37.338.226(00.000.122): 0x0040: 30302032 30300d0a 636f6e74 656e742d : 74797065 3a207465 78742f68 746d6c0d : 00 200..content- type: text/html. 37.338.317(00.000.091): 0x0060: 0a636f6e 74656e74 2d6c656e 6774683a : 20323933 310d0a0d 0a3c6874 6d6c3e0a : .content-length: 2931..... 37.338.439(00.000.122): 0x0080: 20203c68 6561643e 0a202020 203c7469 : 746c653e 44617461 6c6f6767 65722041 : . Datalogger A 37.338.531(00.000.092): 0x00a0: 646d696e 69737472 6174696f 6e3c2f74 : 69746c65 3e0a2020 20203c6c 696e6b20 : dministration. . .. </script>. 37.339.050(00.000.092): 0x0140: 203c7363 72697074 20737263 3d226a71 : 75657279 2d6d696e 2e6a7322 3e3c2f73 : <script src="jq uery-min.js">.. . $(document) (snip)

[bablokb]

Re-based local modifications to the top of LWIP's main line. Performance problems still persist.

Thanks for investing so much time into this problem! So this is an upstream problem in LWIP? Is my interpretation correct?

[eightycc]

This performance bug is giving me a chance to exercise my ramlog module, so just for that reason it's a useful exercise. Also, I enjoy shooting bugs that have a number of asynchronously interacting parts.

Consider my entries in this issue to be a work in progress. For example, yesterday I was convinced that a bug in LWIP was causing the performance glitch during a 3-way TCP handshake detailed above. On reflection and some more study I now see that it is not an LWIP bug but instead it is a combination of an LWIP configuration issue and the way that CircuitPython code handles the process of accepting an incoming TCP socket connection.

[eightycc]

LWIP maintains a 250 ms "fast" timer and a 500 ms "slow" timer. These values probably made sense 20+ years ago, but now cause pain by inducing timeouts that are expensive to recover from. Configuring these to 25 and 50 ms resolves the 3-way TCP handshake delay by reducing the delay processing the first data packet to no more than 25 ms.

LWIP memory management is almost infinitely configurable. Of course this is both a blessing and a curse. I've been experimenting with different static allocations, but that approach leads to solutions that work well for my tests but may be terrible for other use cases. Maybe use all dynamic allocation by substituting tlsf for all of LWIP's static and dynamic allocators?