SoftAp mode : WiFi ping delay is high and unstable (IDFGH-13652)

ShengjieCh commented 1 month ago

Answers checklist.

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

IDF version.

esp-idf-v5.2.2

Espressif SoC revision.

ESP32C6

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.

USB

What is the expected behavior?

In an interference-free environment, the ping delay when WiFi is used as a softAP is low and stable.

What is the actual behavior?

the ping delay is high and unstable.

Steps to reproduce.

Anyway, I tested the ping integrated in default esp-idf iperf example (native, i.e. non-esp-hosted) and found below result over the air test:

Debug Logs.

ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x1 (POWERON),boot:0xe (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:2
load:0x40875720,len:0x1974
load:0x4086c110,len:0x1018
load:0x4086e610,len:0x2f68
entry 0x4086c11a
I (23) boot: ESP-IDF v5.4-dev-1915-g15514919c9-dirty 2nd stage bootloader
I (24) boot: compile time Aug 21 2024 11:52:48
I (25) boot: chip revision: v0.0
I (29) qio_mode: Enabling default flash chip QIO
I (34) boot.esp32c6: SPI Speed      : 80MHz
I (39) boot.esp32c6: SPI Mode       : QIO
I (43) boot.esp32c6: SPI Flash Size : 2MB
I (48) boot: Enabling RNG early entropy source...
I (54) boot: Partition Table:
I (57) boot: ## Label            Usage          Type ST Offset   Length
I (64) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (72) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (79) boot:  2 factory          factory app      00 00 00010000 00100000
I (87) boot: End of partition table
I (91) esp_image: segment 0: paddr=00010020 vaddr=420a8020 size=29ff8h (172024) map
I (134) esp_image: segment 1: paddr=0003a020 vaddr=40800000 size=05ff8h ( 24568) load
I (141) esp_image: segment 2: paddr=00040020 vaddr=42000020 size=a0dc0h (658880) map
I (274) esp_image: segment 3: paddr=000e0de8 vaddr=40805ff8 size=1b524h (111908) load
I (300) esp_image: segment 4: paddr=000fc314 vaddr=40821520 size=03b04h ( 15108) load
I (312) boot: Loaded app from partition at offset 0x10000
I (312) boot: Disabling RNG early entropy source...
I (324) cpu_start: Unicore app
I (332) cpu_start: Pro cpu start user code
I (333) cpu_start: cpu freq: 160000000 Hz
I (333) app_init: Application information:
I (335) app_init: Project name:     iperf
I (340) app_init: App version:      qa-test-full-master-esp32c5-202
I (347) app_init: Compile time:     Aug 21 2024 11:53:25
I (353) app_init: ELF file SHA256:  bd02ecc2c...
I (358) app_init: ESP-IDF:          v5.4-dev-1915-g15514919c9-dirty
I (365) efuse_init: Min chip rev:     v0.0
I (370) efuse_init: Max chip rev:     v0.99
I (375) efuse_init: Chip rev:         v0.0
I (380) heap_init: Initializing. RAM available for dynamic allocation:
I (387) heap_init: At 4082AAC0 len 00051B50 (326 KiB): RAM
I (393) heap_init: At 4087C610 len 00002F54 (11 KiB): RAM
I (399) heap_init: At 50000000 len 00003FE8 (15 KiB): RTCRAM
I (406) spi_flash: detected chip: generic
I (410) spi_flash: flash io: qio
W (414) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (427) sleep: Configure to isolate all GPIO pins in sleep state
I (434) sleep: Enable automatic switching of GPIO sleep configuration
I (441) coexist: coex firmware version: 8da3f50af
I (456) coexist: coexist rom version 5b8dcfa
I (456) main_task: Started on CPU0
I (456) main_task: Calling app_main()
I (464) pp: pp rom version: 5b8dcfa
I (464) net80211: net80211 rom version: 5b8dcfa
I (470) wifi:wifi driver task: 40834b08, prio:23, stack:6656, core=0
I (475) wifi:wifi firmware version: 5ad280023
I (479) wifi:wifi certification version: v7.0
I (483) wifi:config NVS flash: disabled
I (486) wifi:config nano formatting: disabled
I (491) wifi:mac_version:HAL_MAC_ESP32AX_761,ut_version:N, band mode:0x1
I (497) wifi:Init data frame dynamic rx buffer num: 60
I (502) wifi:Init static rx mgmt buffer num: 5
I (506) wifi:Init management short buffer num: 32
I (510) wifi:Init dynamic tx buffer num: 40
I (514) wifi:Init static tx FG buffer num: 2
I (518) wifi:Init static rx buffer size: 1700 (rxctrl:92, csi:512)
I (525) wifi:Init static rx buffer num: 40
I (528) wifi:Init dynamic rx buffer num: 60
I (532) wifi_init: rx ba win: 32
I (536) wifi_init: accept mbox: 6
I (540) wifi_init: tcpip mbox: 64
I (544) wifi_init: udp mbox: 64
I (548) wifi_init: tcp mbox: 64
I (551) wifi_init: tcp tx win: 51200
I (556) wifi_init: tcp rx win: 65535
I (560) wifi_init: tcp mss: 1440
I (564) wifi_init: WiFi IRAM OP enabled
I (568) wifi_init: WiFi RX IRAM OP enabled
I (573) wifi_init: WiFi SLP IRAM OP enabled
I (578) wifi_init: LWIP IRAM OP enabled
I (583) wifi:set country: cc=CN schan=1 nchan=13 policy=0

I (588) wifi:Set ps type: 0, coexist: 0

I (592) phy_init: phy_version 310,dde1ba9,Jun  4 2024,16:38:11
W (644) wifi:ACK_TAB0   :0x   90a0b, QAM16:0x9 (24Mbps), QPSK:0xa (12Mbps), BPSK:0xb (6Mbps)
W (644) wifi:CTS_TAB0   :0x   90a0b, QAM16:0x9 (24Mbps), QPSK:0xa (12Mbps), BPSK:0xb (6Mbps)
W (649) wifi:(agc)0x600a7128:0xd210ab1c, min.avgNF:0xce->0xd2(dB), RCalCount:0x10a, min.RRssi:0xb1c(-78.25)
W (659) wifi:(TB)WDEV_PWR_TB_MCS0:19
W (662) wifi:(TB)WDEV_PWR_TB_MCS1:19
W (665) wifi:(TB)WDEV_PWR_TB_MCS2:19
W (669) wifi:(TB)WDEV_PWR_TB_MCS3:19
W (672) wifi:(TB)WDEV_PWR_TB_MCS4:19
W (675) wifi:(TB)WDEV_PWR_TB_MCS5:19
W (678) wifi:(TB)WDEV_PWR_TB_MCS6:18
W (682) wifi:(TB)WDEV_PWR_TB_MCS7:18
W (685) wifi:(TB)WDEV_PWR_TB_MCS8:17
W (688) wifi:(TB)WDEV_PWR_TB_MCS9:15
W (692) wifi:(TB)WDEV_PWR_TB_MCS10:15
W (695) wifi:(TB)WDEV_PWR_TB_MCS11:15
I (699) wifi:11ax coex: WDEVAX_PTI0(0x55777555), WDEVAX_PTI1(0x00003377).

I (705) wifi:mode : sta (40:4c:ca:4a:a8:50)
I (709) wifi:enable tsf

 ==================================================
 |       Steps to test WiFi throughput            |
 |                                                |
 |  1. Print 'help' to gain overview of commands  |
 |  2. Configure device to station or soft-AP     |
 |  3. Setup WiFi connection                      |
 |  4. Run iperf to test UDP/TCP RX/TX throughput |
 |                                                |
 =================================================

Type 'help' to get the list of commands.
Use UP/DOWN arrows to navigate through command history.
Press TAB when typing command name to auto-complete.
I (840) main_task: Returned from app_main()
iperf>
iperf> ap_set sample sample@123
I (17274) WIFI: DONE.SET_AP_CONFIG,FAIL.12293,ESP_ERR_WIFI_MODE
iperf> wifi_mode apsta
I (22580) WIFI: mode: apsta
I (22581) wifi:mode : sta (40:4c:ca:4a:a8:50) + softAP (40:4c:ca:4a:a8:51)
W (22582) wifi:11ax/11ac mode can not work under phy bw 40M, the softap 2G bandwidth changed to 20M
I (22593) wifi:Total power save buffer number: 20
I (22593) wifi:Init max length of beacon: 752/752
I (22604) wifi:Init max length of beacon: 752/752
I (22605) esp_netif_lwip: DHCP server started on interface WIFI_AP_DEF with IP: 192.168.4.1
I (22605) WIFI: DONE.SET_WIFI_MODE,OK.
iperf> ap_set sample sample@123
I (24417) wifi:Total power save buffer number: 20
I (24418) esp_netif_lwip: DHCP server started on interface WIFI_AP_DEF with IP: 192.168.4.1
I (24419) WIFI: DONE.SET_AP_CONFIG,OK.
iperf>
iperf> I (34470) wifi:new:<1,0>, old:<1,0>, ap:<1,0>, sta:<0,0>, prof:1, snd_ch_cfg:0x0
I (34471) wifi:(trc)phytype:CBW20-SGI, snr:54, maxRate:0, highestRateIdx:0
W (34482) wifi:(trc)band:2G, phymode:3, highestRateIdx:0, lowestRateIdx:11, dataSchedTableSize:14
I (34483) wifi:(trc)band:2G, rate(S-MCS7, rateIdx:0), ampdu(rate:S-MCS7, schedIdx(0, stop:8)), snr:54, ampduState:wait operational
I (34494) wifi:ifidx:1, rssi:-28, nf:-82, phytype(0x3, CBW20-SGI), phymode(0x3, 11bgn), max_rate:0, he:0, vht:0, ht:1
I (34505) wifi:(ht)max.RxAMPDULenExponent:3(65535 bytes), MMSS:6(8 us)
I (34516) wifi:station: a4:cf:99:50:73:55 join, AID=1, bgn, 20
W (34610) wifi:<ba-add>idx:4, ifx:1, tid:6, TAHI:0x1015573, TALO:0x5099cfa4, (ssn:0, win:64, cur_ssn:0), CONF:0xc0006005
I (34611) esp_netif_lwip: DHCP server assigned IP to a client, IP is: 192.168.4.2
I (34623) wifi:[ADDBA]TX addba request, tid:0, dialogtoken:1, bufsize:64, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x0)
I (34642) wifi:[ADDBA]RX addba response, status:0, tid:0/tb:1(0xa1), bufsize:32, batimeout:0, txa_wnd:32
W (35847) wifi:<ba-add>idx:5, ifx:1, tid:0, TAHI:0x1015573, TALO:0x5099cfa4, (ssn:2, win:64, cur_ssn:2), CONF:0xc0000005
iperf>
iperf>
iperf>
iperf>
iperf> ping 192.168.4.2
64 bytes from 192.168.4.2: icmp_seq=1 ttl=64 time=4 ms
iperf> 64 bytes from 192.168.4.2: icmp_seq=2 ttl=64 time=4 ms
64 bytes from 192.168.4.2: icmp_seq=3 ttl=64 time=2 ms
64 bytes from 192.168.4.2: icmp_seq=4 ttl=64 time=4 ms
64 bytes from 192.168.4.2: icmp_seq=5 ttl=64 time=6 ms

--- 192.168.4.2 ping statistics ---
5 packets transmitted, 5 received, 0% packet loss, time 20ms
iperf>
iperf> ping -c 20 192.168.4.2
64 bytes from 192.168.4.2: icmp_seq=1 ttl=64 time=69 ms
iperf> 64 bytes from 192.168.4.2: icmp_seq=2 ttl=64 time=2 ms
64 bytes from 192.168.4.2: icmp_seq=3 ttl=64 time=15 ms
64 bytes from 192.168.4.2: icmp_seq=4 ttl=64 time=7 ms
64 bytes from 192.168.4.2: icmp_seq=5 ttl=64 time=10 ms
64 bytes from 192.168.4.2: icmp_seq=6 ttl=64 time=10 ms
64 bytes from 192.168.4.2: icmp_seq=7 ttl=64 time=5 ms
64 bytes from 192.168.4.2: icmp_seq=8 ttl=64 time=2 ms
64 bytes from 192.168.4.2: icmp_seq=9 ttl=64 time=64 ms
64 bytes from 192.168.4.2: icmp_seq=10 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=11 ttl=64 time=2 ms
64 bytes from 192.168.4.2: icmp_seq=12 ttl=64 time=25 ms
64 bytes from 192.168.4.2: icmp_seq=13 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=14 ttl=64 time=2 ms
64 bytes from 192.168.4.2: icmp_seq=15 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=16 ttl=64 time=20 ms
64 bytes from 192.168.4.2: icmp_seq=17 ttl=64 time=46 ms
64 bytes from 192.168.4.2: icmp_seq=18 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=19 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=20 ttl=64 time=3 ms

--- 192.168.4.2 ping statistics ---
20 packets transmitted, 20 received, 0% packet loss, time 297ms
iperf>
iperf> ping -c 40 192.168.4.2
64 bytes from 192.168.4.2: icmp_seq=1 ttl=64 time=58 ms
iperf> 64 bytes from 192.168.4.2: icmp_seq=2 ttl=64 time=97 ms
64 bytes from 192.168.4.2: icmp_seq=3 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=4 ttl=64 time=8 ms
64 bytes from 192.168.4.2: icmp_seq=5 ttl=64 time=8 ms
64 bytes from 192.168.4.2: icmp_seq=6 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=7 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=8 ttl=64 time=49 ms
64 bytes from 192.168.4.2: icmp_seq=9 ttl=64 time=76 ms
64 bytes from 192.168.4.2: icmp_seq=10 ttl=64 time=4 ms
64 bytes from 192.168.4.2: icmp_seq=11 ttl=64 time=2 ms
64 bytes from 192.168.4.2: icmp_seq=12 ttl=64 time=43 ms
64 bytes from 192.168.4.2: icmp_seq=13 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=14 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=15 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=16 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=17 ttl=64 time=9 ms
64 bytes from 192.168.4.2: icmp_seq=18 ttl=64 time=7 ms
64 bytes from 192.168.4.2: icmp_seq=19 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=20 ttl=64 time=2 ms
64 bytes from 192.168.4.2: icmp_seq=21 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=22 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=23 ttl=64 time=2 ms
64 bytes from 192.168.4.2: icmp_seq=24 ttl=64 time=1 ms
64 bytes from 192.168.4.2: icmp_seq=25 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=26 ttl=64 time=11 ms
64 bytes from 192.168.4.2: icmp_seq=27 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=28 ttl=64 time=18 ms
64 bytes from 192.168.4.2: icmp_seq=29 ttl=64 time=5 ms
64 bytes from 192.168.4.2: icmp_seq=30 ttl=64 time=8 ms
64 bytes from 192.168.4.2: icmp_seq=31 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=32 ttl=64 time=10 ms
64 bytes from 192.168.4.2: icmp_seq=33 ttl=64 time=35 ms
64 bytes from 192.168.4.2: icmp_seq=34 ttl=64 time=59 ms
64 bytes from 192.168.4.2: icmp_seq=35 ttl=64 time=67 ms
64 bytes from 192.168.4.2: icmp_seq=36 ttl=64 time=107 ms
64 bytes from 192.168.4.2: icmp_seq=37 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=38 ttl=64 time=52 ms
64 bytes from 192.168.4.2: icmp_seq=39 ttl=64 time=3 ms
64 bytes from 192.168.4.2: icmp_seq=40 ttl=64 time=4 ms

--- 192.168.4.2 ping statistics ---
40 packets transmitted, 40 received, 0% packet loss, time 787ms

More Information.

https://github.com/espressif/esp-hosted/issues/457

jyc6 commented 1 month ago

我也遇到了这个问题，ap模式还总出现断的情况；

mhdong commented 1 month ago

Hi @ShengjieCh I have already tried to reproduce this issue locally. I was able to reproduce the same phenomenon as you observed. Through packet capture and log analysis, it can be concluded that when the ping latency is high, such as over 50ms, it typically results in BA loss. I also conducted the same test in a shielded box environment, where the issue of high ping latency did not occur. softap_mode_ping_delay.zip STA mac: wlan.addr == 60:55:f9:f6:04:24 AP mac: wlan.addr == 60:55:f9:f6:2e:d1 SSID: testmhd password: 12345678 We will continue to analyze the cause of BA loss. If it is due to environmental interference, we will consider whether to adjust the BA rate control algorithm to enhance the robustness of BA packets.

mhdong commented 1 month ago

hi @jyc6 你好，方便的话请提供一下IDF的版本和复现环境。如果能提供复现的log和抓包，这有利于我们快速的分析问题的原因。

AxelLin commented 3 weeks ago

I was able to reproduce the same phenomenon as you observed. We will continue to analyze the cause of BA loss.

@mhdong Any progress for this issue? (In practice, this symptom is a user visible bug.)

ShengjieCh commented 2 weeks ago

Ping latency test results of chip B：https://pan-sec.djicorp.com/s/H6tq8Tj4xWxDYfW

AxelLin commented 5 days ago

@mhdong Did you check the wireshark log in https://github.com/espressif/esp-idf/issues/14531#issuecomment-2421630444 ? Do you have any update for this issue?

espressif / esp-idf