Call to esp_wifi_sta_get_ap_info significantly delays wifi response (IDFGH-7070)

[mbratch]

Environment

• ESP32 Pico Dev Kit 4.1 running ESP-IDF 4.4 stable version
• CMake build system
• xtensa-esp32-elf-gcc v8.4.0
• Operating System: Windows
• Environment type: PowerShell, Eclipse ESP-IDF
• Power Supply: USB

Problem Description

I'm running an application that acts as a wifi IoT device that connects to my wireless AP. Normally, when I ping the device, the ping response varies between 20ms and 120ms when the application is "idle". This seems excessive already, however, when I start up a task which calls esp_wifi_sta_get_ap_info once per second to obtain the RSSI value, even though this call only takes less than 500us, the ping response of the device varies between about 200ms and 4000ms. It appears that the call to esp_wifi_sta_get_ap_info is ithe wifi handler, but I am not really sure what's actually happening. There's no indication in the ESP-IDF documentation that this might be a concern.

I also found that other HTTP requests to the ESP32 from a client are also disrupted or delayed. They don't seem to get lost, but can be delayed by a few seconds.

Expected Behavior

I would expect a call every second to esp_wifi_sta_get_ap_info to have little or no effect on ping or other network command response.

Actual Behavior

Calling esp_wifi_sta_get_ap_info once per second causes ping response to degrade severely (by about 10x). It often in fact does not respond for several seconds at a time to pings or to other network requests. I can relax the interval for reading RSSI to, say, every 5 seconds. But then the network request will be delayed intermittently accordingly. That is, every few seconds, in that case, a ping response, for example, may be delayed and require 1 second or up to several seconds.

The interference to response is not limited to ping. The REST API server also is delayed by the calls to esp_wifi_sta_get_ap_info in a similar way.

Steps to reproduce

1. Run ESP32 application that connects to wifi
2. Put ESP32 application in a mode which checks RSSI once per second
3. Ping the ESP32 application from another client on the network
4. Observe very slow ping response.

[hpdhabe]

Hello @mbratch, Thanks for reporting the issue. With help of the information that you have provided, we are able to reproduce the issue and are looking into it. This is possibly caused due to messages missing the timing to reply because of the blocking nature of esp_wifi_sta_get_ap_info API, and timing is important as power save is enabled by default in the station example. So meanwhile, if power saving is not an issue, you can try disabling it by making the following API call esp_wifi_set_ps(WIFI_PS_NONE); after esp_wifi_start();. This should fix the normal latency issue and the turnaround time after calling the esp_wifi_sta_get_ap_info API should also not be that high.

[mbratch]

Thank you for the reply. I already have power save turned off for wifi when I observe the issue I reported.

[hpdhabe]

Ohh. The latency on my side after turning off power save seems quite low (2ms to 10ms) compared to when it is on (similar to reported observations https://user-images.githubusercontent.com/7990964/160707521-ed7fe232-09b9-4646-a1d7-26368eacb042.png). Can you please provide a sniffer capture containing the ping data? Please try to either include the communication of AP with other nodes in the network or isolate the test device and ping device altogether.

[mbratch]

@hpdhaba thanks for the quick reply. Overall, what is the ping latency you observe? Without the calls to esp_wifi_sta_get_ap_info I'm seeing a range of ping response times of my ESP32 device of 30-150ms. Average close to 100ms. Is that normal? I ran the basic wifi example application with the same results, so I confirmed it isn't affected by my own wifi event handling.

Regarding the esp_wifi_sta_get_ap_info call, I don't think it matters, but I should indicate that I am calling it from a FreeRTOS software timer function, once per call, at regular intervals.

I will try to get you a sniffer capture. I have to confess I am not practiced at Ethernet sniffer captures, but I really need to be... :)

[hpdhabe]

Overall, what is the ping latency you observe?

40ms to 200ms.

I'm seeing a range of ping response times of my ESP32 device of 30-150ms. Average close to 100ms. Is that normal?

Yes, that is normal in the case of esp32 as the station defaults to power save enabled. If you disable it, it should improve a lot. I got close to 2ms and 20ms.

Regarding the esp_wifi_sta_get_ap_info call, I don't think it matters, but I should indicate that I am calling it from a FreeRTOS software timer function, once per call, at regular intervals.

There is definitely something wrong with the API though. We are trying to get to the bottom of it. Thanks.

[mbratch]

Thank you @hpdhabe . To be clear though, I have always been operating with the wifi power save OFF and my ping response is 30-150ms. It may be longer if I turn on power save. So it seems it is abnormal.

[mbratch]

Hi @hpdhabe I did a couple of Wireshark captures. ws1ap.pcap is without the calls to esp_wifi_sta_get_ap_info. ws2ap.pcap is with a call to esp_wifi_sta_get_ap_info every 2.5 seconds. In each case I'm pinging about 1/sec from the laptop (192.168.1.89) to the ESP32 device (192.168.1.30). I did include the AP (192.168.1.1) in the filter, but I didn't see anything in the capture to/from that address.

wsap.zip

[hpdhabe]

Thanks you for the effort @mbratch.

I took a look at the sniffer capture that you have attached and indeed the response time is more that what it should ideally be. But the key information that is required to make sense of the situation is missing from the sniffer. That might be possible if you had used IP addresses as the filter in wireshark. (ip.addr) instead of MAC addresses (wlan.addr).

I did include the AP (192.168.1.1) in the filter, but I didn't see anything in the capture to/from that address.

This is expected to happen as the WiFi frames will not have IP information. To get those packets, you will have to use wlan.addr.

It will be great if you can update the sniffer capture and also upload the sdkconfig.

[mbratch]

Hi @hpdhabe I did a couple of Wireshark captures based upon MAC address. One without the RSSI calls and one with, as before. See attached file. MAC of my ESP32 device is D8:A0:1D:5D:C0:4C.

wsap_mac.zip

[hpdhabe]

Hi @mbratch, I still cannot see WiFi frames in the capture that you have provided. Can you please elaborate on the setup that you are using for sniffing. It might be possible that you are sniffing on the network instead of sniffing the channel on which the network resides. In which case, you will have to put your sniffing device in monitor mode and sniff the channel. What we are trying to achieve here is, capture the 802.11 packets and by taking a look at them we can access the situation of power save, channel congestions or some other unknown factor.

[mbratch]

@hpdhabe I have Wireshark running on my laptop. From that laptop I am continually pinging the ESP32 device and capturing the packets in wireshark, filtering on the MAC address of the ESP32.

I definitely appreciate what you are after. I am just not sure how to set up to obtain it for you. Can I do it with Wireshark? If so I can do some digging in the documentation for setting it up properly.

[hpdhabe]

@mbratch,

Can I do it with Wireshark? If so I can do some digging in the documentation for setting it up properly.

Yes, you will ultimately have to use Wireshark. But first, put your laptop in Monitor mode and then sniff the WLAN interface. Here are some resources that might help you to capture 80211 packets. If you are using a Windows machine, try: https://www.youtube.com/watch?v=As9BUoOMk_A If you are using an iOS machine, try: https://www.macupdate.com/app/mac/56809/airtool/old-versions If you are using a Linux machine, try:

ifconfig wlp0s20f3 down
iwconfig wlp0s20f3 mode monitor
ifconfig wlp0s20f3 up
iwconfig wlp0s20f3 channel 3
wireshark

Please note that a lot of WiFi cards (NIC) don't support putting them in monitor mode. So it is vital to check the compatibility of your laptop's NIC. Hope that helps.

[mbratch]

Sadly, I don't think the wifi hardware on my laptop (Qualcomm Atheros QCA9377) supports monitor mode. At least Wireshark didn't recognize it to support it. I do have a Linux server but it's on the wired network. If I were to ping my ESP32 from the server it's going through wired then wireless but will it capture what I need?

[not-my-real-name]

I am also having this issue. I have one network setup where the ping delays go from 50-100ms normally to 1.5 seconds or more. I have another network where it seems to be much worse and it misses pings entirely for 5-6 seconds. I think I do have power saving enabled.

I'm also running 4.4. My own branch with minimal fixes. Last merged point was 121ddb87e5 ("Merge branch 'bugfix/fix_adc_digital_not_reset_issue_v4.4' into 'release/v4.4'", 2022-03-08)

Some observations: I can poll the RSSI (via my own Modbus lib and UART) and it returns super quickly (~20ms). If I poll it quickly (~100ms) it returns a different RSSI value each time. So it is doing something and it does it fast. So it seems to be an issue with returning to a normal operating state after fetching the AP info.

I have access to the right adapter to capture packets (wifi monitor mode), but it's been a long time since I tried to do it. I can have a go at capturing something if it is helpful? I have not yet tried with power saving disabled.

[not-my-real-name]

I have tried it with power saving disabled.

esp_wifi_set_ps(WIFI_PS_NONE);

This does reduce my normal pings to <10ms. It also does seem to work fine regardless of how often I call esp_wifi_get_sta_ap_info().

I'm probably not going to bother capturing packets as it seems the issue as far as I can observe it has been reproduced already. Is there anything to be learned from my network that doesn't reply at all for 5+ seconds after calling this function with power saving enabled?

[hpdhabe]

Hi @not-my-real-name, your results match the testing that I have done.

Is there anything to be learned from my network that doesn't reply at all for 5+ seconds after calling this function with power-saving enabled?

It is that the issue is with the power save mechanism and I have also raised a fix for the same. The ping with power-save mode enabled should now not be more than 200-250ms and should ideally be below 100ms regardless of which API is being called.

I can have a go at capturing something if it is helpful?

I think we can pass on this since the root issue has already been isolated. And thanks for considering.

I have raised a fix for the master branch but it will take time for it to be back-ported on other release branches. @mbratch This issue will automatically close once the change is available on the latest master.

[mbratch]

Hello @hpdhaba. As I mentioned in a prior comment, I have the problem even though I have WiFi power save turned off. However, I would still like to try the fix when available in case it still resolves my issue before deciding that the issue I raised is closed.

Some observations: I can poll the RSSI (via my own Modbus lib and UART) and it returns super quickly (~20ms). If I poll it quickly (~100ms) it returns a different RSSI value each time. So it is doing something and it does it fast. So it seems to be an issue with returning to a normal operating state after fetching the AP info.

I have a similar observation. I timed the return from esp_wifi_sta_get_ap_info actually to be much less than 1ms. It definitely returns quickly, but seems to leave the wifi in a "dazed" state momentarily.

Ping responses to my ESP32 "normally" take 30-150ms even in power save mode. I ran the sample wifi smartconfig application, and get similar results.

[EternityForest]

I believe I might be seeing a related issue. I'm seeing total lockups that I haven't fully tracked down, but seem to be in a micropython function that calls this API, with power save enabled.

[jack0c]

@mbratch @EternityForest The fix have been merge to master internally, 51f6091761be0c69b64d6310dcb72082dd5965d8 , please check if you can find it on GitHub.

[mbratch]

@jack0c I may not be reading the commit 51f6091 correctly, but does the commit only affect ESP32s3 and ESP32c3? My processor is ESP32-pico-d4.

[Espressif-liuuuu]

Hi @mbratch , it does fix all chips. Since no WiFi rom code on esp32, there is no modification in esp32.rom.ld.

[mbratch]

@Espressif-liuuuu great, thank you!

[Alvin1Zhang]

Thanks for reporting, feel free to reopen.