ESP32 millis() overflows break the loop

nikuz · January 16, 2019, 11:38am

Ok, I’ll try it again. But as I said, I definitely got the same error even with BlynkTimer.

Costas · January 16, 2019, 11:39am

That’s not the problem.

@nikuz we need to see a minimal sketch that demonstrates your problem.

nikuz · January 16, 2019, 11:42am

It doesn’t matter actually, because I have another piece of important code in a loop. It’s a serial communication read, and I can’t remove it.

But what the beauthifull design? If the library can’t work properly if so insignificant piece of code is written beside of blynk api requests?

nikuz · January 16, 2019, 11:46am

Yeh, I’ll try to produce it. Yesterday I definitely got that error on the code slightly different from which I posted before. Everytime I need to wait one to few hours to reproduce it.

Costas · January 16, 2019, 11:48am

I only had to wait a few seconds to test your earlier sketches. Just add 4294950000 ms to now / millis() to trigger the rollover without waiting for 71 minutes.

nikuz · January 16, 2019, 11:59am

Did you see the [0] Heartbeat timeout: 0, 4293769, 4293745 message in the logs? It alwais happens when a real rollover happen. The code of the end of the loop just show a real uptime even the rollover happened. If you can’t change the millis() return value, you can’t trigger the the rollover.

Costas · January 16, 2019, 12:01pm

But you should be able to simulate the rollover with code.

nikuz · January 16, 2019, 12:22pm

How? If blynk library depends on the millis() function. Please ignore my code which just print the uptime. Blynk timers just stop to run after the real rollover. Again, I tried with the internal BlynkTimer, and definitely got this error. I’ll focus reproduce this on the clear code today. I’ll write when I’ll get the error with exact code.

Costas · January 16, 2019, 12:41pm

@vshymanskyy how does your skipTimes addition to SimpleTimer handle millis() rollover?

From https://github.com/blynkkk/blynk-library/blob/1de0dfd9e867e6ae26178a8d016538d2cc05ede5/src/utility/BlynkTimer.cpp

                unsigned long skipTimes = (current_millis - timer[i].prev_millis) / timer[i].delay;
                // update time
                timer[i].prev_millis += timer[i].delay * skipTimes;

Costas · January 16, 2019, 12:51pm

@vshymanskyy looks like it probably has the effect of stopping timers.

Maybe something like this instead:

                unsigned long skipTimes;
                if(current_millis > timer[i].prev.millis)
                {
                  skipTimes = (current_millis - timer[i].prev_millis) / timer[i].delay;  
                }
                else
                {
                  timer[i].prev.millis =  current_millis;  
                }

Costas · January 16, 2019, 1:09pm

By hacking the libraries.

You could have tried adding 4294950000 ms to current_millis / timer[i].prev.millis etc.

I didn’t look at the libraries too closely but I suspect none of the SimpleTimer versions, Blynk’s included handles the rollover that well. The new Blynk version with skipTimes probably works badly in your particular case of very frequent sync’s etc.

nikuz · January 16, 2019, 8:21pm

Here is the code which gave me the loop break now

#define BLYNK_DEBUG // Optional, this enables lots of prints
#define BLYNK_PRINT Serial

#include <WiFi.h>
#include <BlynkSimpleEsp32.h>

const char *SSID = "";
const char *PSWD = "";

char blynkAuth[] = "";
char blynkDomain[] = "192.168.1.4";
const uint16_t blynkPort = 8080;

const unsigned long blynkConnectAttemptTime = 5L * 1000L;  // try to connect to blynk server during only 5 seconds
BlynkTimer blynkTimer1;
BlynkTimer blynkTimer2;

const unsigned long updateInterval = 1L * 1000L;

void blynkSync1() {
    Blynk.virtualWrite(V1, "1");
}

void blynkSync2() {
    Blynk.virtualWrite(V2, "2");
}

void blynkSync3() {
    Blynk.virtualWrite(V3, "3");
}

void blynkSync4() {
    Blynk.virtualWrite(V4, "4");
}

void blynkSync5() {
    Blynk.virtualWrite(V5, "5");
}

void blynkSync6() {
    Blynk.virtualWrite(V6, "5");
}

void blynkSync7() {
    Blynk.virtualWrite(V7, "5");
}

void blynkSync8() {
    Blynk.virtualWrite(V8, "5");
}

void blynkSync9() {
    Blynk.virtualWrite(V9, "5");
}

void blynkSync10() {
    Blynk.virtualWrite(V10, 1);
}

void blynkSync11() {
    Blynk.virtualWrite(V11, 1);
}

void blynkSync12() {
    Blynk.virtualWrite(V12, 1);
}

void blynkSync13() {
    Blynk.virtualWrite(V13, 1);
}

void blynkSync14() {
    Blynk.virtualWrite(V14, 1);
}

void blynkSync15() {
    Blynk.virtualWrite(V15, 1);
}

void blynkSync16() {
    Blynk.virtualWrite(V16, 1);
}

void blynkSync17() {
    Blynk.virtualWrite(V17, 1);
}

void blynkSync18() {
    Blynk.virtualWrite(V18, 1);
}

void blynkSync19() {
    Blynk.virtualWrite(V19, 1);
}

void blynkSync20() {
    Blynk.virtualWrite(V20, 1);
}

void blynkSync21() {
    Blynk.virtualWrite(V21, 1);
}
void blynkSync22() {
    Blynk.virtualWrite(V22, 1);
}
//

void blynkConnect() {
    if (WiFi.isConnected() && !Blynk.connected()) {
        unsigned long startConnecting = millis();
        while (!Blynk.connected()) {
            Blynk.connect();
            if (millis() > startConnecting + blynkConnectAttemptTime) {
                Serial.println("Unable to connect to Blynk server.\n");
                break;
            }
        }
    }
}

void setup() {
    Serial.begin(115200);
    while (!Serial) { ;
    }

    WiFi.mode(WIFI_STA);
    WiFi.begin(SSID, PSWD);

    for (int loops = 10; loops > 0; loops--) {
        if (WiFi.isConnected()) {
            Serial.println("");
            Serial.print("IP address: ");
            Serial.println(WiFi.localIP());
            break;
        } else {
            Serial.println(loops);
            delay(1000);
        }
    }
    if (!WiFi.isConnected()) {
        Serial.println("WiFi connect failed");
    }

    Blynk.config(blynkAuth, blynkDomain, blynkPort);
    blynkConnect();

    blynkTimer1.setInterval(1000L, blynkConnect);
    blynkTimer1.setInterval(2000L, blynkSync1);
    blynkTimer1.setInterval(2050L, blynkSync2);
    blynkTimer1.setInterval(2100L, blynkSync3);
    blynkTimer1.setInterval(2150L, blynkSync4);
    blynkTimer1.setInterval(2200L, blynkSync5);
    blynkTimer1.setInterval(2250L, blynkSync6);
    blynkTimer1.setInterval(2300L, blynkSync7);
    blynkTimer1.setInterval(2350L, blynkSync8);
    blynkTimer1.setInterval(2400L, blynkSync9);
    blynkTimer1.setInterval(2450L, blynkSync10);
    blynkTimer1.setInterval(2500L, blynkSync11);
    blynkTimer1.setInterval(2550L, blynkSync12);
    blynkTimer1.setInterval(2600L, blynkSync13);
    blynkTimer1.setInterval(3050L, blynkSync14);
    blynkTimer2.setInterval(3100L, blynkSync15);
    blynkTimer2.setInterval(3150L, blynkSync16);
    blynkTimer2.setInterval(3200L, blynkSync17);
    blynkTimer2.setInterval(3250L, blynkSync18);
    blynkTimer2.setInterval(3300L, blynkSync19);
    blynkTimer2.setInterval(3350L, blynkSync20);
    blynkTimer2.setInterval(3400L, blynkSync21);
    blynkTimer2.setInterval(3450L, blynkSync22);
}

void loop() {
    if (Blynk.connected()) {
        Blynk.run();
    }
    blynkTimer1.run();
    blynkTimer2.run();

    uint32_t now = millis();
    static uint32_t lastUpdate = 0;
    static uint32_t overFlowCounter = 0;
    if (now < lastUpdate) { // overflow
        overFlowCounter++;
        lastUpdate = now;
    }
    if (now - lastUpdate > updateInterval){
        lastUpdate = now;
        Serial.print("uptime = ");
        Serial.println((overFlowCounter * 4294968) + now);
    }
}

Logs:

...
uptime = 7817532
[3522581] <[14|00|F6|00|06]vw[00]4[00]4
[3522650] <[14|00|F7|00|06]vw[00]9[00]5
[3522718] <[14|00|F8|00|07]vw[00]13[00]1
[3522787] <[14|00|F9|00|07]vw[00]17[00]1
[3522854] <[14|00|FA|00|07]vw[00]12[00]1
[3523031] <[14|00|FB|00|07]vw[00]16[00]1
[3523181] <[14|00|FC|00|07]vw[00]14[00]1
[3523331] <[14|00|FD|00|06]vw[00]2[00]2
uptime = 7818533
[3523581] <[14|00|FE|00|07]vw[00]21[00]1
[3523681] <[14|00|FF|00|07]vw[00]11[00]1
[3523781] <[14|01|00|00|06]vw[00]5[00]5
[3523849] <[14|01|01|00|07]vw[00]19[00]1
[3523931] <[14|01|02|00|06]vw[00]6[00]5
[3524081] <[14|01|03|00|06]vw[00]3[00]3
[3524151] <[14|01|04|00|07]vw[00]15[00]1
[3524219] <[14|01|05|00|06]vw[00]1[00]1
[3524431] <[14|01|06|00|07]vw[00]10[00]1
uptime = 7819534
[3524581] <[14|01|07|00|06]vw[00]7[00]5
[3524650] <[14|01|08|00|06]vw[00]8[00]5
[3524731] <[14|01|09|00|06]vw[00]4[00]4
[3524981] <[14|01|0A|00|06]vw[00]9[00]5
[3525049] <[14|01|0B|00|07]vw[00]20[00]1
[3525181] <[14|01|0C|00|07]vw[00]13[00]1
[3525249] <[14|01|0D|00|07]vw[00]18[00]1
[3525316] <[14|01|0E|00|07]vw[00]12[00]1
[3525384] <[14|01|0F|00|06]vw[00]2[00]2
...
uptime = 8589719
[4294781] <[14|01|C3|00|06]vw[00]3[00]3
[4294851] <[14|01|C4|00|07]vw[00]13[00]1
[4294919] <[14|01|C5|00|07]vw[00]16[00]1
[0] Heartbeat timeout: 0, 4286091, 4285549
[1] Connecting to 192.168.1.4:8080
[13] <[02|00|01|00] c9caa42869de4ea6a087520f68814788
[3016] Login timeout
[5016] Connecting to 192.168.1.4:8080
[5027] <[02|00|01|00] c9caa42869de4ea6a087520f68814788
[5315] >[00|00|01|00|C8]
[5315] Ready (ping: 286ms).
[5382] <[11|00|02|00]Fver[00]0.5.4[00]h-beat[00]10[00]buff-in[00]1024[00]dev[00]ESP32[00]build[00]Jan 16 2019 16:14:20[00]
[7297] >[00|00|02|00|C8]
[15385] <[06|00|03|00|00]
[16527] >[00|00|03|00|C8]
[25389] <[06|00|04|00|00]
[26985] >[00|00|04|00|C8]
[35393] <[06|00|05|00|00]
[35805] >[00|00|05|00|C8]
[45397] <[06|00|06|00|00]
[45692] >[00|00|06|00|C8]
[55401] <[06|00|07|00|00]
[58402] <[06|00|08|00|00]
[59239] >[00|00|07|00|C8]
[59603] >[00|00|08|00|C8]
[68404] <[06|00|09|00|00]
[71405] <[06|00|0A|00|00]
[74406] <[06|00|0B|00|00]
[77407] <[06|00|0C|00|00]
[78604] Heartbeat timeout: 78604, 59603, 77407
[82408] Connecting to 192.168.1.4:8080
[82421] <[02|00|01|00] c9caa42869de4ea6a087520f68814788
[82938] >[00|00|01|00|C8]
[82939] Ready (ping: 517ms).
[83006] <[11|00|02|00]Fver[00]0.5.4[00]h-beat[00]10[00]buff-in[00]1024[00]dev[00]ESP32[00]build[00]Jan 16 2019 16:14:20[00]
[83912] >[00|00|02|00|C8]
[93009] <[06|00|03|00|00]
[96010] <[06|00|04|00|00]
[99011] <[06|00|05|00|00]
[102012] <[06|00|06|00|00]
[102913] Heartbeat timeout: 102913, 83912, 102012
[107013] Connecting to 192.168.1.4:8080
[107022] <[02|00|01|00] c9caa42869de4ea6a087520f68814788
[107629] >[00|00|01|00|C8]
[107629] Ready (ping: 605ms).
[107696] <[11|00|02|00]Fver[00]0.5.4[00]h-beat[00]10[00]buff-in[00]1024[00]dev[00]ESP32[00]build[00]Jan 16 2019 16:14:20[00]
[107823] >[00|00|02|00|C8]
[117701] <[06|00|03|00|00]
[118191] >[00|00|03|00|C8]
[127705] <[06|00|04|00|00]
[128156] >[00|00|04|00|C8]
[137709] <[06|00|05|00|00]
[138211] >[00|00|05|00|C8]
[147713] <[06|00|06|00|00]
[147778] >[00|00|06|00|C8]
[157718] <[06|00|07|00|00]
[159056] >[00|00|07|00|C8]
[167722] <[06|00|08|00|00]
[168059] >[00|00|08|00|C8]
[177726] <[06|00|09|00|00]
...

nikuz · January 16, 2019, 8:28pm

Uptime of my main app, which avoid to do something around the millis() rollover is more than 9 hours for now. It’s a new record.

vshymanskyy · January 17, 2019, 9:33am

The maximum value of millis should be the max uint32 value, which is 4'294'967'295 ms. That would take 49.7 days for this issue to happen. Dou you know why on ESP32 it overflows on 4294967 ms?

Costas · January 17, 2019, 9:38am

@vshymanskyy that’s a good point about the 50 days.

I rarely use the ESP32 and most of what I do is for ESP8266’s.

uint32 when used for deepSleep() is based on microseconds rather than milliseconds and therefore maximum deepSleep was 71 minutes until recently.

uint64 is now available which in theory gives a maximum deepSleep of thousands of years. Espressif have capped this to a practical level of about 3.5 hours.

Maybe the ESP32 is working on microseconds?

nikuz · January 17, 2019, 10:19am

Yeh, it was my first question. Here is the answer:

github.com/espressif/arduino-esp32

Strange loop behaviour on minimal sketch

opened 01:59PM - 08 Jan 19 UTC

closed 09:27PM - 08 Jan 19 UTC

nikuz

### Hardware: Board: ESP32 Dev Module Core Installation/update date: M…on Jan 7 IDE name: Arduino IDE 1.8.6 Flash Frequency: 40Mhz PSRAM enabled: no Upload Speed: 921600 Computer OS: Mac OSX ### Description: The below minimal sketch hangs the device at the 4294290 millisecond. I mean serial just stops to print, without any errors, and the last number always 4294290. My DebugLevel set to "error". What the magic? I tried it many many times. Every time I have to wait more than hour to get this error. But this is stable reproduces on the ff18a211e4638784d7d892e500c9fe67e36eeae7 commit. And it doesn't reproduce on the 1.0.0 release. Sketch just prints the uptime in milliseconds once in second without interrupts by `delay`. ### Sketch: ```cpp #include <Arduino.h> const unsigned long printUptimeTimer = 1L * 1000L; unsigned long printUptimeLastTime = 0; void setup() { Serial.begin(115200); while (!Serial) { ; } } void loop() { unsigned long now = millis(); if (printUptimeTimer < now && now - printUptimeTimer > printUptimeLastTime) { Serial.println(millis()); printUptimeLastTime = millis(); } } ``` ### Debug Messages: ``` nothing ```

Costas · January 17, 2019, 10:30am

Looks like ESP32 still needs a lot of development if it doesn’t understand the basics of a millisecond.

jtthewoodworker · January 20, 2019, 7:16pm

Using unsigned values to calculate time differences has some tricks. In order to determine a time delay from a previously captured time, you have to do a subtract in order for the rollover to be taken care of automatically by overflow and truncation. If you compare the current time to a value + a desired delay, you will have trouble at the rollover.

For instance if the current time recently rolled over and = 5 milliseconds and you previously saved a start time that’s lets say for example, the max value time could be (0xFFFFFFFFUL), and then also, lets assume you’re trying to measure a time delay of 1000 milliseconds.

So, assuming all variables are unsigned long:
SavedTime = 0xFFFFFFFFUL;
CurrentTime = 5;
DesiredDelay = 1000;

In unsigned math, using a subtraction in the comparison yields:
(CurrentTime - SavedTime > DesiredDelay) = (5 - 0xFFFFFFFF > 1000), where 5 - 0xFFFFFFFF = 6. This is the correct comparison: Is the elapsed time (6) greater than 1000 milliseconds.

If you do an addition in the comparison it yields:
(CurrentTime > SavedTime + DesiredDelay) = (5 > 0xFFFFFFFF + 1000), where 0xFFFFFFFF + 1000 = 4095 due to rollover. This is an incorrect comparison: Is 5 greater than 4095. This comparison will be correct except when the current time has rolled over and the saved time has not.

For sure, this line should be rewritten from this:
if (millis() > startConnecting + blynkConnectAttemptTime) {
to this:
if (millis() - startConnecting > blynkConnectAttemptTime) {

I also have questions about rollover affecting the print statement:
Serial.println((overFlowCounter * 4294968) + now);
This could easily not print what you’re expecting. The constant 4294969 is an int. And, “now” can be the max value of an unsigned long. So all together, you could have overflow and wrap around here. Maybe print all 3 values separately to see their true values before the math.

My $0.02. Hope it helps.

Also just noticed this: “((2^32)-1)/1000” from the link to another article you provided. That would defeat using rollover math until this gets fixed. What I said is still value if you don’t get a millis() that has been divided by 1000. %)

vshymanskyy · January 20, 2019, 8:02pm

@jtthewoodworker thanks. I think you’re completely right, you just expressed my thoughts.

nikuz · January 21, 2019, 2:16am

As a conclusion of my initial problem:

I do not use the BlynkTimer, instead I use a slightly modified SimpleTimer with taking care about millis() overflows. Here is the run method:

void MyTimer::run() {
    int i;
    unsigned long current_millis;
    bool overflowIncreased = false;

    // get current time
    current_millis = elapsed();

    for (i = 0; i < MAX_TIMERS; i++) {
        // no callback == no timer, i.e. jump over empty slots
        if (callbacks[i]) {
            // is it time to process this timer ?
            // see http://arduino.cc/forum/index.php/topic,124048.msg932592.html#msg932592
            if (current_millis < prev_millis[i]) { // overflow
                if (!overflowIncreased) {
                    overFlowCounter++;
                    overflowIncreased = true;
                }
                prev_millis[i] = current_millis;
            }

            if (current_millis - prev_millis[i] >= delays[i]) {
                // update time
                prev_millis[i] = current_millis;
                (*callbacks[i])();
            }
        }
    }
}

I do not do any blocking operations 10 seconds around overflows.

And my app working very stable for days. Not a single hang or glitch.