espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.85k stars 7.32k forks source link

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

Open DeeFuse opened 1 month ago

DeeFuse commented 1 month ago

Answers checklist.

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 commented 1 month ago

@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!