netconn_recv has ~200ms delay and return packets in bunches (IDFGH-13905)

[DeeFuse]

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v5.3.1

Espressif SoC revision.

ESP-WROOM-32D

Operating System used.

Windows

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

PowerShell

Development Kit.

Custom Board

Power Supply used.

External 5V

What is the expected behavior?

When using netconn to receive sACN packets (UDP) netconn_recv shall return frames as soon as they are received by the SOC
At 10 packet per second, the output shall be like "Delay 100" at every packet.

What is the actual behavior?

The frames read from netconn_recv arrive grouped in 200ms bunches.
The Log shows the Delay is around 200ms on the first print, then 1ms for the second (when sending 10 packets per second)

Steps to reproduce.

Load project based on Wifi getting started to connect to WIFI as Station.
Setup a UDP listener (simplified)

netconn_bind(conn, IP_ADDR_ANY, E131_DEFAULT_PORT);
netconn_join_leave_group(conn, &multiaddr, &netif_default->ip_addr, NETCONN_JOIN);
uint32_t lastTick = 0;
while(1) {
    struct netbuf *buf;

    err = netconn_recv(conn, &buf);
    if(err != ERR_OK) {
	ESP_LOGE(TAG, "Error: Failed to receive packet. err=%d\n", err);
	continue;
    }
    if(buf->p->tot_len == 638) {
    	uint32_t now = esp_timer_get_time();
        ESP_LOGW(TAG, "Delay %ld", (now - lastTick) / 1000);
        lastTick = now;
    }
    netbuf_delete(buf);
}

Debug Logs.

W (17984) E1.31: Delay 203
W (17984) E1.31: Delay 1
W (18184) E1.31: Delay 203
W (18404) E1.31: Delay 212
W (18404) E1.31: Delay 1
W (18594) E1.31: Delay 195
W (18594) E1.31: Delay 1
W (18804) E1.31: Delay 203
W (18804) E1.31: Delay 1
W (18904) example: Pkg 9
W (19004) E1.31: Delay 203
W (19004) E1.31: Delay 1
W (19214) E1.31: Delay 203
W (19214) E1.31: Delay 1
W (19414) E1.31: Delay 203
W (19414) E1.31: Delay 1
W (19654) E1.31: Delay 234
W (19654) E1.31: Delay 1
W (19824) E1.31: Delay 172
W (19824) E1.31: Delay 2
W (19904) example: Pkg 10
W (20034) E1.31: Delay 203
W (20234) E1.31: Delay 204
W (20234) E1.31: Delay 1
W (20444) E1.31: Delay 203
W (20444) E1.31: Delay 1
W (20644) E1.31: Delay 203
W (20644) E1.31: Delay 1
W (20854) E1.31: Delay 203
W (20854) E1.31: Delay 1

More Information.

This effect is also observable at higher rates. e.g. at 30 frames per second the "Delay 1" is print 3 times in a row.
I confirmed the timing is correct by using a Laptop on the same Wifi and tracing the Packets with Wireshark.
This behaviour is also observabel when using Broadcast UPD Packets and using BSD sockets.
Running the socket on APP / PRO Core did not have a effect.
Changing RX Buffer size / cound did noch have a effect.
I've also added esp_wifi_set_ps(WIFI_PS_NONE); to the wifi initialisation

[hansw123]

@DeeFuse
sorry for late reply!
could you post the wireshark capture? maybe Delay 1 is caused by ampdu。
In a real-world environment, sending wifi packets won't be so idealized, and conflicts and delays may occur so that the ap may perform AMPDUs, leading to a situation where the STA receives several packets at the same time.
To know the true reason still need the wireshark capture,hope your reply!