800-900ms between loop() latency during wifi connection handling

[braddr]

Basic Infos

• This issue complies with the issue POLICY doc.
• I have read the documentation at readthedocs and the issue is not addressed there.
• I have tested that the issue is present in current master branch (aka latest git).
• I have searched the issue tracker for a similar issue.
• If there is a stack dump, I have decoded it.
• I have filled out all fields below.

Platform

• Hardware: [ESP-WROOM-02]
• Core Version: [2.4.1-braddr see pull Eliminate gigantic blocking time inside ESP8266WiFiMulti::run #4888]
• Development Env: [makeEspArduino]
• Operating System: [Ubuntu]

Settings in IDE

• Module: [Generic ESP8266 Module]
• Flash Mode: [qio]
• Flash Size: [2MB/1MB]
• lwip Variant: [v2 Lower Memory]
• Reset Method: [http updater]
• Flash Frequency: [40Mhz]
• CPU Frequency: [80Mhz]
• Upload Using: [OTA]

Problem Description

Trying to find and reduce sources of > 10ms latencies and there's a repeatable 850-900ms between-loop latency after calling WiFi.begin(...) and before the WiFi.status() transitions to connected.

I'm opening this now without having identified the source of the latency for two reasons. 1) to give me a place to document my findings, and 2) in hopes that someone with internal knowledge will have pointers to provide.

MCVE Sketch

#include <ESP8266WiFi.h>

void setup() {
    Serial.begin(74880);
    Serial.println();
    WiFi.persistent(false);
    WiFi.setAutoConnect(false);
    WiFi.begin("apname", "password");
}
void loop() {
    static unsigned long exit_ms  = millis(), enter_ms = millis(), counter = 0;
    counter++;
    enter_ms = millis();
    unsigned long delta = enter_ms - exit_ms;
    if (delta > 10) Serial.printf("%d ms: between loop #%d\n", delta, counter);
    exit_ms = millis();
}

Debug Messages

SDK:2.2.1(cfd48f3)/Core:2.4.1/lwIP:2.0.3(STABLE-2_0_3_RELEASE/glue:arduino-2.4.1)

mode : sta(84:f3:eb:a1:89:03) + softAP(86:f3:eb:a1:89:03)
add if0
wifi evt: 8
wifi evt: 2
scandone
state: 0 -> 2 (b0)
887 ms: between loop #251586
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 5
cnt 

connected with BradNet2, channel 11
dhcp client start...
wifi evt: 0
ip:192.168.0.42,mask:255.255.255.0,gw:192.168.0.1
wifi evt: 3
wifi evt: 7

[devyte]

The request in the ssue template is for an MCVE sketch. Your issue is for latency between loops, but younhave WiFiMulti and httpUpdater in there. Please reduce your sketch to the bare minimum that shows your issue.
WiFiMulti in particular does a whole lot of things inside run().

[braddr]

I pulled out the WiFiMulti, since it's definitely not needed (forest for the trees issues when minimizing -- this is already a ton smaller than the original code base it's extracted from. The updater is harder for me to pull out since that's how I'm getting the code to the board.

[braddr]

I put together another board with both rx and tx so I could serial program rather than ota and reduced the sketch predictably significantly.

The between loop time disappears when changing the persist and autoconnect settings, but not super consistently. Or at least I haven't figured out the pattern yet. Post-programming reset vs power on reset seems to make a difference at times too.

[devyte]

Have you seen discussion in #4751 ?

I think that there are some sdk things related to wifi that (obviously) happen between loops. My understanding is that there is a wrapper function that calls loop() and then just reschedules itself for the next execution by the sdk. Between those calls, the sdk handles its own internal upkeep.

Also, persistent and autoconnect do have an impact. I saw a table of startup times somewhere, and those two settings played a big role in ESP's startup time, together with dhcp vs. static IP usage.

I'm not sure that there is anything that can be done in this repo.

[braddr]

I hadn't seen that issue yet, and it's interesting, but tangential to this issue. That issue discusses a bit of fluctuation in # of loop iterations per second. In this case, I'm reporting a blip of a single case of a nearly 1 second delay between loops. I know that the loop is a slave to the sdk loop. I guess the question is, is anything at the Arduino layer setting up a task that could cost that much or is it all down at the sdk level? If it's purely sdk driven, then I agree that there's likely little if anything that can be done here.

History question: is there a reason that the arduino layer is based on the no os sdk rather than the freertos based sdk? It's really tempting to experiment with re-homing it to the rtos.

[devyte]

The loop sdk task and loop wrapper can be found in this file. Let me know if you find anything significant that could be improved.

The reason I mentioned #4751 is that the graphs there show sharp periodic downward spikes. A downward spike in a loops/s curve means a short-interval slowdown, which could be due to something happening in between loops, such as what you're observing here. If it's the same phenomenon, and I think it is, then it's pretty much confirmed that there is nothing to do here.

History answer: the freeRTOS requires additional heap for its internals, and then each spawned task requires its own stack and event queue. Overall, the amount of free heap that you have left over for your own app is significantly less than here with the NONOS sdk. Considering that an SSL connection requires ~20KB of heap, use of the NONOS sdk over the freeRTOS is a no-brainer.
In addition, the extra code built into an app increases flash size by a significant amount, both due to the freeRTOS libs themselves, and due to the additional boilerplate of IPC. With this NONOS sdk there are already reported cases of users hitting the bin size limit, or going over what fits on their flash, so with the freeRTOS it gets a lot worse.
Bottom line; this SDK is leaner and more lightweight, so you can fit more functionality in your app. It just requires that you program in a different way, and take certain precautions as well as observe certain restrictions.

[earlephilhower]

This really looks like an SDK issue and is filed against an ancient release of the Core and SDK. We were seeing random delays in the SDK blob with pre 3.0, but have moved to a more stable version and those seem to be cleared up. If you upgrade to the latest version (GIT would be preferable) and still see this, do please open a new bug with some more info.