Loop on 8266 gets slower and slower the longer it runs.

[ondabeach]

I was running 2.30 core on a NodeMCU and ran into this problem, so I updated to the latest (2.41) and the problem persists.

Anyone know what is going on here?

Running the simple sketch below demonstrates what seems to be a timing drift of some sort. As soon as the sketch starts the time taken to loop increases quite quickly. Then it stabilises for a while and only varies by a few loops second by second before dropping quickly by around 1000 iterations per second then stabilizing again for a while. It just seems to keep going in the same fashion as you can see by the output below the sketch.

The gaps in the output are where I have edited out most of the output from the stable periods so this post wasn't thousands of lines long.

SKETCH: //////////////////////////////////////////////////// long lastTime; long loops=0;

void setup(){ Serial.begin(115200); } void loop(){ loops++; if(millis()>=lastTime+1000){ Serial.println(String(loops)); loops=0; lastTime=millis(); } } ////////////////////////////////////////////////////////////

OUTPUT: ////////////////////////////////////////////////////// 112312 112313 112311 112312 112312 112311 112312 112312 112311 112314 112312 112314 111547 110907 110911 110907 110908 110908 110909 110909 110908 110907 110909 110909 110904 110909 110909 110909 110907 110907 110910 110909 110907 110909 110908 110910 110908 110906 110910 110908 110907 110911 110907 110910

110908 110910 110909 110910 110909 110912 110910 110312 109539 109541 109540 109541 109537 109539 109541 109540 109539 109542 109540 109541 109540 109541 109541 109540 109539 109541 109540 109541

109541 109541 109539 109541 109541 109541 109541 109247 108206 108205 108204 108209 108204 108205 108205 108203 108205 108205 108203 108206 108204 108205 /////////////////////////////////////////////////////////////////////////////

[Makuna]

not related specifically to your issue, but more to the error in how you testing for time passed. Millis returns an unsigned value, you don't want to check > or <. Your code does not work in all cases and includes time not being tracked ...

if  (millis()>=lastTime+1000){ // this doesn't work when rollover happens
  // blah blah blah
    lastTime=millis();  // ddn't account for the time between the two millis() calls
}

the better way to do it...

uint32_t currentTime = millis(); // store away one millis to work with
if  (currentTime - lastTime > 1000) { // compare the delta works for unsigned
  // blah blah blah
    lastTime=currentTime;
}

[tonton81]

you could also do:

static uint32_t theTime = millis();
if ( millis() - theTime > 1000 ) {
  theTime = millis();
  // Do whatever here
}

It's simpler to use and understand

[ondabeach]

@makuna and @tonton81 you didn't even bother to understand the issue. Stop making irrelevant, unhelpful posts.

The point is to count the number of loops the processor can get through in 1 second and check the number of iterations for consistency over time.

The result is that the number of iterations per second decreases with time. It happens quite quickly. Within a few minutes the iterations reduce by around 10,000 and it just keeps getting slower.

[tonton81]

that was quite harsh, maybe you should brush up on your “community” skills

[tonton81]

better yet, you have a problem, both in code and in mentality.

[ondabeach]

@tonton81 your post had nothing to do with the issue I was reporting. You didn't try the sketch. You didn't even understand the problem. How exactly is pointing out totally irrelevant coding niceties supposed to help?

[tonton81]

the fact that you’re casting a long as a String to print, and using a long for millis() speaks alot about how your coding sucks. take that into consideration next time you tell others about making unhelpful posts. Goto a forum as this isn’t a core issue and learn some respect, and go learn basic programming while you’re at it. Our “unhelpful posts” show an issue with your code, an “issue” that you neglect to seek out and correct, so rather than fix your code you tell two people that they’re unhelpful, yet, the only code on this “issue” thats correct is Makunas and mine.

Our code is not irrelevant, it shows the flaws in yours and I just pointed out the obvious, you’re lucky someone spoke up, most people don’t care to correct others. If this is the way people act in response, then you will never get help.

[Pablo2048]

To calm this down i have some questions:

1. is wifi on or off when testing?
2. if on - is Wifi connected? Maybe it depend on how much wifi traffic goes around when measuring...

[ondabeach]

@Pablo2048 a sensible question. The same thing happens with wifi turned on or off.

[devyte]

Alright enough, let's keep things civil here. @ondabeach you ignored the issue template, and you didn't even bother to use markup for your code. Code niceties and whatever may not be essential for a particular code problem, but the procedure here and issue policy exist for a reason. Several, actually. If you can't be bothered to take 5 minutes to open an issue properly, don't expect anyone to spend the effort to understand it properly. Also, @Makuna specifically said that his comment was not directly related to your issue.

@tonton81 yes, it was harsh, even abrasive, and his communication skills could use a lot of work, but he didn't insult. You did. Please restrain yourself in the future. Also, your != you're.

Now, how about discussing the specifics of the issue? My understanding is that the loop() function gets called as scheduled SDK task, and it gets scheduled again and again. In other words, we, as in this core, don't really have control over how often it gets called. My suggestion: test the way that loop() gets called here in a build environment that is not this core, i.e.: some other ESP development framework. In other words, implement a function that gets scheduled over and over again, and measure the number of times per second that it gets called. If the timing issue is reproduced there, then the issue is in the SDK, and it should be reported to Espressif.

[Pablo2048]

Well, I do have simple CPU load monitoring in my applications (idea grabed somewhere from the internet) - the method count loop() for 30 seconds, update maximum value and then compute CPU load in %. I have never observed behavior you have described...

[ondabeach]

@devyte Arduino IDE is the only dev tool I have for programming the 8266, and other modules for that matter. I wasn't suggesting that the issue is the core, merely that I've tried the latest core and the problem persists.

For my project I'm probably going to use the Maple Mini as it iterates through the same loop 3 times as fast as an 8266 does, even with WiFi off and running at 160mhz.

But, it's a simple test and the problem is evident within seconds of running the sketch. The issue may well be in the SDK, but I'm sure it's worth investigating by someone as involved in the core as yourself. No doubt you could prove where it lies one way or the other very quickly and easily.

[ondabeach]

@Pablo2048 run the sketch in my first post on an 8266 and you will see the behaviour as described.

[torntrousers]

When you say you've tried it with Wifi off was that by booting with RF_DISABLED? Otherwise there's quite a lot going on on the background which will slow things down as it tries to connect to Wifi and DHCP etc. Also what about if you run it for longer - many minutes or hours? Does it settle down into a more steady loop time?

[tonton81]

Correcting users on their grammar your/you’re shouldn’t be tolerated either, in fact, it’s worse than what happened earlier. If we speak our native language here (french) you can’t judge a person by their linguistics, otherwise it’s the same boat as earlier. If we’re going to start correcting users on their grammar provided they’re not speaking their native language for the benefit of the forums/github community, then we are dealt with racism as a whole. I can’t help but see users come on here every day who don’t speak english, and who try their best at it, who are we to tell them they are not speaking or talking your language or not google translating :) Would you like me to tell users to correct their grammar when they post their issue? I understand you try to keep “morals” in order, but correcting users on a language thats secondary to them is not a motivation/practice either for the public as a whole.

[devyte]

@tonton81 Grammar correction has absolutely nothing to do with racism. My intent was to point out a recurring mistake to you, so that you may correct yourself and improve. And before you throw racism around in the context of native English, you should know that I'm latin american, I live in Chile, and my native tongue is Spanish. You have now needlessly insulted both a user and a developer. Now please either move on, or help with the issue at hand. Ou si tu veux nous pouvons avoir une conversation privée et sérieusement insulter l'un a l'autre.

[tonton81]

We could keep arguing but I’m not here for that, this is getting off topic and I agree enough is enough and no need to speak french, some people won’t understand it :)

It’s also good to know correcting others is not racism, although, wouldn’t you think it will not piss them off? Or perhaps they take it the wrong way if they don’t understand? If not, it would be awesome to correct others knowing it’s not intimidating them. Thanks for letting us all know that it’s alright to do so.

[ondabeach]

@torntrousers
I used WiFi.mode(WIFI_OFF) which doesn't require putting the esp into deep sleep. I confirmed that the WiFi was indeed off as there is no SSID visible and current consumption was way down.

[devyte]

@ondabeach what happens over a longer time period? Does it monotonically drop? Does it stabilize? Does it oscillate? The first case makes this critical, I.e.: effort should be spent investigating. The latter two make me inclined to note the behavior, i.e. document the variations, and leave it as is. Also, is there a correlation between loops/s and the ESP's temperature?

[ondabeach]

@devyte The longest I've let it run is 10 minutes and it continues to drop. Yes, the drop pattern is monotonical. It drops a couple of thousand iterations within a few seconds of starting. Then it stabilises for about 30 seconds. Then it drops another couple of thousand iterations over the space of only about 3 seconds. Then it stabilises for around another 30 seconds. Then it drops another couple of thousand iterations over the space of only about 3 seconds. Then it stabilises for around another 30 seconds and keeps repeating that pattern for as long as I've run the test to this point.

If you look at the output in my original post, each line is the number of loop iterations which are reported every 1 second. where the blank lines are between the groups of numbers is where the iteration count was stable for the approx. 30 seconds so I deleted them to keep the post from being a mile long.

The behaviour is the same with a cold module first thing in the morning or after running all day. It does not seem to be temperature related.

[devyte]

@ondabeach what about heap? Could you please fix your sketch to account for millis overflow, and let it run e.g. overnight, or over a couple of days?

[ondabeach]

@devyte what do you want to know or see in regard to the heap?

I will mod as suggested, start the sketch running and report back what happens in the long term.

[WereCatf]

I am not seeing the issue here. I just tested this for ~10 minutes and the number of loop-iterations it does in one second varies by about ~300 loops/s, but it never goes below that, ie. I get between 95.3k - 95.6k iterations per second.

uint32_t prevMillis;
uint32_t numLoops = 0;

void setup() {
  Serial.begin(115200);
  delay(1000);
  Serial.println("Begin...");
  delay(500);
  prevMillis = millis();
}

void loop() {
  if((millis() - prevMillis) >= 1000){
    Serial.println("Loops elapsed in 1s: " + String(numLoops));
    numLoops = 0;
    prevMillis = millis();
  }
  numLoops++;
}

EDIT: Forgot to mention that I am on the latest git. I also tested OP's original code and I cannot replicate the issue with it, either.

[ondabeach]

@WereCatf thanks for your time in testing this. What version of Arduino IDE are you using? What 8266 core version are you using? What module are you running the sketch on?

The starting iteration count in all instances is around 210000.

I ran your code on 2 different versions of NodeMCU and an esp-01 and they all exhibit the same monotonical pattern of iteration decramentation as outlined in my OP.

[WereCatf]

@ondabeach Like I said, I am using the latest git-code. Try with that and see if the issue persists or not.

[ondabeach]

@WereCatf As my OP states, I am using the latest core. I am using IDE 1.8.5

What version of Arduino IDE are you using? What module type are you using?

[RudyFiero]

95888 at the start for me. 95338 about 11-12 hours later (now).

I am using 1.8.6 and git from last week.

include

long lastTime;
long loops = 0;

void setup() {
  Serial.begin(115200);
  ESP.eraseConfig();
  WiFi.mode( WIFI_OFF );
  WiFi.forceSleepBegin();
  }
void loop() {
  loops++;
  if (millis() >= lastTime + 1000) {
    Serial.println(String(loops));
    loops = 0;
    lastTime = millis();
  }
}

[WereCatf]

@ondabeach IDE-version really shouldn't matter, since it's not the one doing the compiling, but 1.8.5. Also, ESP-12E.

As for core-version: you are saying you use the 2.4.1 - version. This was released a couple of months back, it's not the same thing as latest code from the git.

[ondabeach]

@WereCatf fair comment on the 2.4.1 as opposed to the latest git ver. I will download and try but I'd bet London to a brick that it won't make any difference.

I'd be interested to see the output of the first 100 seconds or so from your setup. As I intimated earlier, the first and last iteration counts of a 12 hour period don't tell much of a story.

[ondabeach]

@RudyFiero I ran your code and below is the first 100 seconds of output:

A start and end iteration count does not demonstrate the pattern of decramentation you are experiencing.

225337 222689 222415 220198 219663 219662 219664 218023 216980 216981 216980 216981 216980 216980 216981 216396 214361 214363 214361 214362 214361 214361 214363 214361 214361 214362 214361 214363 214361 214361 214363 214361 213222 211807 211807 211807 211805 211806 211807 211805 211805 211807 211806 211807 211805 211806 211806 211806 211805 211808 211805 211807 211805 211806 211807 211805 211806 211807 211805 211803 211805 211806 211807 211805 211805 211810 209581 209311 209309 209310 209310 209310 209309 209311 209309 209311 209309 209310 209310 209310 209309 209311 209309 209311 209310 209309 209311 209309 209309 209311 209310 209310 209310 209309 209311 209309 209311 209311 209309 @devyte the decramentation pattern is not quite monotonical. The stable period increases in length with each phase of decramentation, which itself remains quite constant in that the number of iterations decreases by around the same amount (roughly 1%) over the space of only 3 seconds.

Very strange indeed.

I don't think others quite grasp the relevance of the finer details of the pattern of decramentation.

As I said earlier, I will not be using an 8266 module for the project I am currently working on. I do not need WiFi but the advertised speed of the 8266 and ESP32 modules (160mhz and 240mhz) had me going to them first. But, unfortuantely they do not deliver anything like the expected performance. A Maple Mini running at 72mhz can iterate the same loop at over 1.3mhz compared to the best I've achieved from an espressif module of around 220khz. The Maple Mini is also much more stable from the moment it starts.

This issue lost importance to me very early on, however I kept reporting on it as I thought it worth investigating. But if you want to put it in the too hard basket then feel free to close this issue.

On the other hand if you want to keep investigating then I am happy to put the time in to help as the espressif modules do contribute greatly to the success of my business.

[WereCatf]

@ondabeach https://pastebin.com/zDi5SGVs -- as you can see, the issue is not present.

[RudyFiero]

At first I thought this was a non-issue. But I did wonder what would happen over the period of a month or year. I might do a test like this with a battery backed up ESP and see where it goes.

[ondabeach]

I had to kick down some pretty thick doors to get people to take me seriously when I reported the PUYA flash chip issue.

There are some very clever people around here, sometimes though, they can't see the forest for the trees.

Fortunately however, I'm nothing if not persistent :)

[Makuna]

Board version 2.4.1, with the following sketch and output. Running at 80mhz. What I am seeing is that as a "timer" is doubled, the issue occures and stabilizes; and then just seems to cycle down and up.

#include <ESP8266WiFi.h>

uint32_t lastTime;
long loops = 0;
uint32_t seconds = 0;

void setup()
{
  Serial.begin(115200);

  ESP.eraseConfig();
  WiFi.mode( WIFI_OFF );
  WiFi.forceSleepBegin();

  while (!Serial); // wait for serial attach
  Serial.println("starting...");

  lastTime = millis();
}

void loop()
{
  loops++;

  uint32_t currentTime = millis(); 
  uint32_t delta = currentTime - lastTime;
  if  (delta > 1000) 
  { 
    seconds++;

    Serial.print(loops);
    Serial.print(" ");
    Serial.println(seconds);

    loops = 0;
    lastTime = currentTime;
  } 
}

output summary

starting...
116102 1
114733 2
114690 3
114691 4
114689 5
114687 6
114691 7
114691 8
114689 9
113838 10
113227 11
113229 12
kept going down
111805 58
111802 59
111382 60
110411 61
110413 62
110415 63
110413 64 
stabilied for a bit around 110413
110413 126
110061 127
109057 128
109058 129
stablized and continued down 
109058 259
109058 260
108824 261
107735 262
107734 263
107733 264
107735 265
then stabilized again and continued down
107722 529
106446 530
another drop and stabilize
106444 1064
106445 1065
105590 1066
105186 1067
105184 1068
and yet another drop and stabilize
105184 2135
105185 2136
105184 2137
105177 2138
103952 2139
103951 2140
and yet another change, but not a drop, and takes longer to stabalize
103953 4283
116748 4284
119388 4285
117881 4286
117210 4287
116478 4288
115686 4289
115684 4290
115686 4291
115256 4292
114197 4293
114199 4294
114197 4295
114199 4296
114199 4297
114197 4298
114199 4299
114197 4300
112882 4301
112749 4302
112748 4303
112748 4304
112748 4305
112748 4306
112750 4307
112748 4308
112748 4309
112749 4310
112748 4311
112748 4312
112750 4313
112748 4314
112750 4315
112891 4316
112699 4317
111492 4318
111490 4319
111490 4320
a little change
114197 4300
112882 4301
another soon after
112750 4315
112891 4316
112699 4317
111492 4318
111490 4319
and more adjustments
110108 4415
110109 4416
110110 4417
109320 4418
108763 4419
108759 4420
108762 4421
and few more random interesting samples where values change by more that a few

110422 12865
120300 12866
118432 12867
...
110108 12998
109798 12999
108760 13000
...
106161 13937
105351 13938
104908 13939

And when I discontunied my test...

last sample was

106161 26623

105071.5 average 103529 min 122065 max 104907 Median

[WereCatf]

I think I started seeing the issue now myself, too. I think I'll let it run for a few more hours and see then.

[torntrousers]

...the decramentation pattern is not quite monotonical. The stable period increases in length with each phase of decramentation... - Dude! Where's my dictionary...

I've tried your original and some of the other code posted in this issue and the results I get seem pretty stable. With your original code I get values around 182161 which is quite a lot more than the numbers you get which seems odd.

[WereCatf]

@torntrousers You are probably running your ESP at 160MHz instead 80MHz, aren't you?

[torntrousers]

I've tried both. The original bug report doesn't mention the speed used.

[RudyFiero]

With your original code I get values around 182161 which is quite a lot more than the numbers you get which seems odd.

I found that elevation makes a difference in performance. . . (kidding)

[lrmoreno007]

I can reproduce the problem with this chinese NodeMCU (esp12e):

This config:

And this sketch:

#include <ESP8266WiFi.h>

uint32_t lastTime;
long loops = 0;
uint32_t seconds = 0;
long first;
long lowest = 2147483647;
long highest;

void setup() {
  Serial.begin(115200);

  ESP.eraseConfig();
  WiFi.mode( WIFI_OFF );
  WiFi.forceSleepBegin();

  while (!Serial); // wait for serial attach
  Serial.println("starting...");

  lastTime = millis();
}

void loop() {
  loops++;

  uint32_t currentTime = millis();
  uint32_t delta = currentTime - lastTime;
  if  (delta > 1000) {
    seconds++;
    Serial.print("LOOPS ");
    Serial.print(loops);
    Serial.print(" SECONDS ");
    Serial.print(seconds);
    if (seconds == 1) first = loops;
    if (loops > highest) highest = loops;
    if (loops < lowest) lowest = loops;
    Serial.print(" FIRST ");
    Serial.print(first);
    Serial.print(" LOW ");
    Serial.print(lowest);
    Serial.print(" HIGH ");
    Serial.println(highest);

    loops = 0;
    lastTime = currentTime;
  }
}

This is the result (updated):

LOOPS 94791 SECONDS 20176 FIRST 95162 LOW 94565 HIGH 95295

and here a graphic (updated):

As an observation, I get less loops / seconds than all of you, even with the original sketch.

[lrmoreno007]

I have found a pattern, every 1199 seconds a fall spike occurs. For the big drop peak I have not found a pattern yet.

What happens every 1199-1200 seconds?

[tonton81]

hook up wireshark, maybe a keep-alive? network activity would show there

[lrmoreno007]

@tonton81 WiFi is OFF

[tonton81]

well you never know if a bug can cause the wifi stack to fully shut down or not. :)

[lrmoreno007]

(7 * 1199) + 1 (first one) = 8394 seconds

LOOPS 94770 SECONDS 8391 FIRST 95162 LOW 94639 HIGH 95295 LOOPS 94770 SECONDS 8392 FIRST 95162 LOW 94639 HIGH 95295 LOOPS 94770 SECONDS 8393 FIRST 95162 LOW 94639 HIGH 95295 LOOPS 94629 SECONDS 8394 FIRST 95162 LOW 94629 HIGH 95295 LOOPS 94771 SECONDS 8395 FIRST 95162 LOW 94629 HIGH 95295 LOOPS 94770 SECONDS 8396 FIRST 95162 LOW 94629 HIGH 95295 LOOPS 94770 SECONDS 8397 FIRST 95162 LOW 94629 HIGH 95295

is repeated

[ondabeach]

@tonton81 read the thread more thoroughly. The problem occurs with WiFi turned off.

[ondabeach]

As @devyte said, this problem might not be in the 8266 core. It might be in the espressif SDK. It would be good if someone can see if the problem happens when using IDF and not the core.

[RudyFiero]

11 hours ago I started one that also printed out the heap, and there has been no change in that.

[ondabeach]

@RudyFiero can you restart the sketch and post the first 100 seconds or so of output.

[lrmoreno007]

I have updated the graph up to 20177 seconds (5.6 hours) and there has been a rise in the loops.

This may indicate that at the end it stabilizes within a range, drawing a graph in the form of a saw blade.

I must cut this test now, tomorrow I will try to do it longer, I will decrease the sampling to 15-20 seconds and I will try to use another different module to discard hardware issues (at least in the pattern of peaks)

I will update the previous post to not extend this.