Performance drifting down over time?

Projects General Guidance
1

Hi!
N00b to embedded question:

I have a Seeed RP2040, and am noticing a performance drag over time.
Adapted some other found code to a minimal setup to eliminate my own code/demonstrate.

int Power = 11;
long lastMillis = 0;
long loops = 0;


void setup() {
  pinMode(Power, OUTPUT);
  digitalWrite(Power, HIGH);
  Serial.begin(57600);
  long currentMillis = millis();
  while (true) {
    currentMillis = millis();
    loops++;
    if (currentMillis - lastMillis >= 1000) {
      Serial.print("ms:");
      Serial.print(currentMillis - lastMillis);
      Serial.print(" loops ");
      Serial.println(loops);

      lastMillis = currentMillis;
      loops = 0;
    }
  }
}

void loop(void) {
}

Starts off pretty good (tho for a 133mhz I kinda expected a little more :smirk:)
ms:1000 loops 111906
ms:1000 loops 110556
ms:1000 loops 110164
ms:1000 loops 109213
ms:1000 loops 108838
ms:1000 loops 108792
ms:1000 loops 108463
ms:1000 loops 107862
ms:1000 loops 107548
ms:1000 loops 107471
ms:1000 loops 107198
ms:1000 loops 107360
ms:1000 loops 107208
ms:1000 loops 107092
ms:1000 loops 106849
ms:1000 loops 106443
ms:1000 loops 106326
ms:1000 loops 106183
but over time it just keeps going lower and lower. I've let it keep running, and now I'm seeing
ms:1000 loops 97072
ms:1000 loops 97380
ms:1000 loops 97168
ms:1000 loops 97084
ms:1000 loops 96949
ms:1000 loops 97110
ms:1000 loops 96869
ms:1000 loops 96818
ms:1000 loops 96900

There's a lot of variability in the second-by-second results too, for relatively invariant code, hasn't bottomed out yet, but it does appear to be slowing down.

Application being considered is a long running small neopixel display (which isn't even in here right now) so if it drops too low eventually it will start missing timing requirements.

Something I am or am not doing right?
Thanks!
-B

2

...oops.

...ditto.

3

:+1: "adapted code" :smirk: changed to unsigned longs, didn't impact drift.

4

What happens if you press reset? Do the numbers go back up to the higher figures or do they stay around the same?

What if you disconnect the Arduino for 10 mins and restart?

What if you use micros() instead of millis() (and print every 1000000us)?

5

It’s not clear to me how the RP2040 is clocked , and that might be the issue .

The spec shows a 12Mhz crystal “ for perfect timing” but the processor runs at 133Mhz .

Maybe the processor clock is not very well controlled and hence as it warms the clock slows - I don’t know the answer but maybe someone knows the answer here ????

As an aside , I would never use millis for any long term timing on any Arduino- they all drift to an exten

Also … that code prints before setting current millis , that causes an additional delay in your loop - might be the cause *, set current millis before the print.
There are examples in the IDE which are better .

  • can’t look at code on my iPhone , just things I’d consider
6

Blockquote
What happens if you press reset? Do the numbers go back up to the higher figures or do they stay around the same?

Immediately return to original values and then start moving down

Blockquote
What if you disconnect the Arduino for 10 mins and restart?

Have not tried yet, but unit does not get noticeably warmer than room temp

Blockquote
What if you use micros() instead of millis() (and print every 1000000us)?

That seems more consistent?
us:1000000 loops 223999
us:1000004 loops 224000
us:1000003 loops 223990
us:1000001 loops 223997
us:1000001 loops 223999
us:1000000 loops 223999
us:1000001 loops 223998
us:1000004 loops 223999
us:1000002 loops 224000
us:1000003 loops 223999
us:1000004 loops 224000
us:1000002 loops 224000
us:1000002 loops 224000
us:1000003 loops 224000
us:1000001 loops 223999
us:1000004 loops 223999

7

Let us know. But I suspect same effect as pressing reset.

Yes. And twice the number of loops each second... Strange!

8

Blockquote
Also … that co

:grinning: true but its so darn small and that form factor was desirable for the application.

Wasn't using millis as anything other than checking, I just had noticed it dragging a little on performance and was trying to figure out if it was my code or something else.

Blockquote
set current millis before the print

added deltaMillis so I could to that, no change in behavior

9

Disclaimer: not familiar with the RP2040.

Even stranger if you try it on an old Nano; using micros() reduces the number of loops from around 300,000 to around 174,000.

But in both cases (original code and micros() code), results are far more consistent than what OP gets (ran tests for about 5 minutes)

Original:

ms:1000 loops 300015
ms:1000 loops 299707
ms:1000 loops 300015
ms:1000 loops 299707
ms:1000 loops 300015
ms:1000 loops 299707
ms:1000 loops 300015
ms:1000 loops 300014
ms:1000 loops 299708
ms:1000 loops 300014
ms:1000 loops 299708
ms:1000 loops 300014
ms:1000 loops 299708
ms:1000 loops 300014
ms:1000 loops 300015
ms:1000 loops 299707

micros() code

int Power = 13;
unsigned long lastMicros = 0;
unsigned long loops = 0;


void setup() {
  pinMode(Power, OUTPUT);
  digitalWrite(Power, HIGH);
  Serial.begin(57600);
  long currentMicros = micros();
  while (true) {
    currentMicros = micros();
    loops++;
    if (currentMicros - lastMicros >= 1000000)
    {
      Serial.print("ms:");
      Serial.print((currentMicros - lastMicros)/1000);
      Serial.print(" loops ");
      Serial.println(loops);

      lastMicros = currentMicros;
      loops = 0;
    }
  }
}

void loop(void) {
}

micros() result

ms:1000 loops 174647
ms:1000 loops 174646
ms:1000 loops 174647
ms:1000 loops 174646
ms:1000 loops 174648
ms:1000 loops 174646
ms:1000 loops 174648
ms:1000 loops 174646
ms:1000 loops 174646
ms:1000 loops 174647
ms:1000 loops 174646
ms:1000 loops 174647
ms:1000 loops 174646
ms:1000 loops 174647
ms:1000 loops 174646
ms:1000 loops 174647
ms:1000 loops 174647
ms:1000 loops 174646

Other observation:
Removing the printing of the delta time improves the number of loops; this makes me think that this has everything to do with the serial interrupts. As mentioned, I'm not familiar with the RP2040 so might be on the wrong track.

10

What if you move the contents of the while (true) { } loop into loop(), allowing loop() to be used as intended. Does that slow the number of loops power second? Do you still see the slow-down over time?

int Power = 11;
unsigned long lastMillis = 0;
long loops = 0;


void setup() {
  pinMode(Power, OUTPUT);
  digitalWrite(Power, HIGH);
  Serial.begin(57600);
}
void loop() {
    unsigned long currentMillis = millis();
    loops++;
    if (currentMillis - lastMillis >= 1000) {
      Serial.print("ms:");
      Serial.print(currentMillis - lastMillis);
      Serial.print(" loops ");
      Serial.println(loops);

      lastMillis = currentMillis;
      loops = 0;
    }
}
11

Don't do it that way if you want to have equally distant times. Instead use
lastMillis += 1000;

1 Like
12 
void setup() {
  Serial.begin(115200);
}

void loop(void) {
  static unsigned long lastMillis = 0;
  static unsigned long currentMillis = millis();
  static unsigned long loops = 0;

  loops++;
  if (loops == 1000000UL) {
    currentMillis = millis();
    Serial.print(F("ms: "));
    Serial.println(currentMillis - lastMillis);
    lastMillis = currentMillis;
    loops = 0;
  }
}
13

Heh. No slowdown here, using a Pico board and the Philhower core.


ms:1000 loops 1124406
ms:1000 loops 1124406
ms:1000 loops 1124405
ms:1000 loops 1124407
ms:1000 loops 1124405
ms:1000 loops 1124422
ms:1000 loops 1124406
ms:1000 loops 1124421
ms:1000 loops 1124406
ms:1000 loops 1124407
ms:1000 loops 1124420
ms:1000 loops 1124407
ms:1000 loops 1124421
ms:1000 loops 1124421
ms:1000 loops 1124406
ms:1000 loops 1124421
ms:1000 loops 1124406
ms:1000 loops 1124422
ms:1000 loops 1124420
ms:1000 loops 1124406

(Yeah, there's an extra digit in those numbers compared to OP. "Interesting.")
(Unfortunately, I apparently can't compile with Arduino's RP2040 core, because the included python is trying to load a dynamic library that doesn't work on my 10.13 MacOS when it tries to run "imgtool" Sigh.)

14

If I remember correctly the math does not work out well for 12 MHz. If they're using anything close to the standard Arduino core then the root cause is "they didn't bother to make a correct millis".

15

Wow. I can confirm OP's results. Plus my "MBED runs 1/10th the speed of a non-MBED version, and 1/3 the speed of an Uno.) Very depressing...

loop speed check
Arduino Uno
ms:1000 loops 298643
ms:1000 loops 300015
ms:1000 loops 299707
ms:1000 loops 300015
ms:1000 loops 299707
ms:1000 loops 300015
ms:1000 loops 299707
ms:1000 loops 300015
ms:1000 loops 300014

loop speed check
Philhower core RASPBERRY_PI_PICO
ms:1000 loops 287267
ms:1000 loops 1124395
ms:1000 loops 1124403
ms:1000 loops 1124420
ms:1000 loops 1124406
ms:1000 loops 1124420
ms:1000 loops 1124406
ms:1000 loops 1124408
ms:1000 loops 1124421
ms:1000 loops 1124402

loop speed check
Arduino MBED Pico
ms:1000 loops 100914
ms:1000 loops 100094
ms:1000 loops 99666
ms:1000 loops 99001
ms:1000 loops 98744
ms:1000 loops 98721
ms:1000 loops 98355
ms:1000 loops 97880
ms:1000 loops 97641
ms:1000 loops 97625
ms:1000 loops 97350
ms:1000 loops 97651
ms:1000 loops 97355
ms:1000 loops 97350
ms:1000 loops 97050
ms:1000 loops 96742
ms:1000 loops 96633
ms:1000 loops 96589
ms:1000 loops 96332
ms:1000 loops 96511
ms:1000 loops 96343
ms:1000 loops 96290

I'm suspecting something in the SerialIUSB driver for the slowdown, actually. Probably some fancy lock that doesn't get properly unlocked... :frowning:

Oh, it probably doesn't help that the platform.txt for the MBed Builds leaves out any compiler optimization setting. Though it didn't make a difference in the times I was seeing (I wonder if the MBed library is also built without optimization?)

Sigh. Sigh. Sigh.

16

Hey all, we are away from primary mac for holiday. Windows 11 laptop has issues uploading so will be back at it tomorrow night. I moved the code away from loop() initially to make sure it wasn't something behind the scenes causing the slowdown. be glad to put it back to verify. No change letting it sit for a bit so doesn't seems to be clock heating up.

I do have a design in mind to remove serial from testing part to check if that is causing the diff. Still think something is up in general, the clock of this chip should be moving a lot more loops and some of the other info from folks shows other chips running rings around it :upside_down_face:
Thanks! -B

17

Sorry for the delay, hectic week.
so I've done a couple of tests, now
I wrote this which does both usec and msec tests for 1 minute each in the same file, and delays the output until after the tests run to remove any serial issues.
I ran this with usec first then msec, and then swapped, the numbers are still showing up weird.

int Power = 11;
unsigned long lastmicro = 0;
unsigned long lastmilli = 0;
unsigned long tests = 0;
unsigned long loops = 0;
// we're going to test for ~1 minute
#define TESTS 60

unsigned long microsec[TESTS];  // loops counted/sec by usec
unsigned long millisec[TESTS]; // loops counted/sec by msec
unsigned long maxmicros = 0;    // max number of loops/sec by usec
unsigned long maxmillis = 0;    // max number of loops/sec by msec
unsigned long curcount;         // current counter (usec/msec)

void setup() {
  // pinMode(Power, OUTPUT);
  // digitalWrite(Power, HIGH);
  Serial.begin(57600);

  tests = 0;
  lastmilli = millis();
  while (true) {
    curcount = millis();
    loops++;
    if (curcount - lastmilli >= 1000) {
      // store results
      millisec[tests++] = loops;
      loops = 0;
      lastmilli += 1000;
      if (tests == TESTS)
        break;
    }
  }
  tests = 0;
  lastmicro = micros();
  while (true) {
    curcount = micros();
    loops++;
    if (curcount - lastmicro >= 1000000) {
      // store results
      microsec[tests++] = loops;
      loops = 0;
      lastmicro += 1000000;
      if (tests == TESTS)
        break;
    }
  }

  for (tests = 0; tests < TESTS; tests++) {
    Serial.print("usec test #");
    Serial.print(tests);
    Serial.print(" loops: ");
    Serial.println(microsec[tests]);
  }
  for (tests = 0; tests < TESTS; tests++) {
    Serial.print("msec test #");
    Serial.print(tests);
    Serial.print(" loops: ");
    Serial.println(millisec[tests]);
  }
}

void loop(void) {
}

Results with usec, then msec:

usec test #0 loops: 210784
usec test #1 loops: 222832
usec test #2 loops: 222833
usec test #3 loops: 222833
usec test #4 loops: 222833
usec test #5 loops: 222834
usec test #6 loops: 222833
usec test #7 loops: 222833
usec test #8 loops: 222834
usec test #9 loops: 222833
usec test #10 loops: 222833
usec test #11 loops: 222834
usec test #12 loops: 222833
usec test #13 loops: 222833
usec test #14 loops: 222834
usec test #15 loops: 222833
usec test #16 loops: 222833
usec test #17 loops: 222834
usec test #18 loops: 222833
usec test #19 loops: 222833
usec test #20 loops: 222834
usec test #21 loops: 222833
usec test #22 loops: 222833
usec test #23 loops: 222834
usec test #24 loops: 222833
usec test #25 loops: 222833
usec test #26 loops: 222834
usec test #27 loops: 222833
usec test #28 loops: 222833
usec test #29 loops: 222834
usec test #30 loops: 222833
usec test #31 loops: 222833
usec test #32 loops: 222834
usec test #33 loops: 222833
usec test #34 loops: 222833
usec test #35 loops: 222834
usec test #36 loops: 222833
usec test #37 loops: 222833
usec test #38 loops: 222834
usec test #39 loops: 222833
usec test #40 loops: 222833
usec test #41 loops: 222834
usec test #42 loops: 222833
usec test #43 loops: 222833
usec test #44 loops: 222834
usec test #45 loops: 222833
usec test #46 loops: 222833
usec test #47 loops: 222834
usec test #48 loops: 222833
usec test #49 loops: 222833
usec test #50 loops: 222834
usec test #51 loops: 222833
usec test #52 loops: 222833
usec test #53 loops: 222834
usec test #54 loops: 222833
usec test #55 loops: 222833
usec test #56 loops: 222834
usec test #57 loops: 222833
usec test #58 loops: 222833
usec test #59 loops: 222834
msec test #0 loops: 62183
msec test #1 loops: 62244
msec test #2 loops: 62232
msec test #3 loops: 62146
msec test #4 loops: 62123
msec test #5 loops: 62039
msec test #6 loops: 61982
msec test #7 loops: 62100
msec test #8 loops: 62052
msec test #9 loops: 62019
msec test #10 loops: 62061
msec test #11 loops: 61996
msec test #12 loops: 61929
msec test #13 loops: 61940
msec test #14 loops: 62084
msec test #15 loops: 61991
msec test #16 loops: 61974
msec test #17 loops: 61872
msec test #18 loops: 61961
msec test #19 loops: 61840
msec test #20 loops: 61854
msec test #21 loops: 61762
msec test #22 loops: 62107
msec test #23 loops: 61973
msec test #24 loops: 61994
msec test #25 loops: 61864
msec test #26 loops: 61975
msec test #27 loops: 61875
msec test #28 loops: 61874
msec test #29 loops: 61763
msec test #30 loops: 61948
msec test #31 loops: 61871
msec test #32 loops: 61859
msec test #33 loops: 61752
msec test #34 loops: 61844
msec test #35 loops: 61771
msec test #36 loops: 61736
msec test #37 loops: 61671
msec test #38 loops: 61971
msec test #39 loops: 62026
msec test #40 loops: 61980
msec test #41 loops: 61909
msec test #42 loops: 61941
msec test #43 loops: 61910
msec test #44 loops: 61854
msec test #45 loops: 61798
msec test #46 loops: 61869
msec test #47 loops: 61906
msec test #48 loops: 61868
msec test #49 loops: 61810
msec test #50 loops: 61795
msec test #51 loops: 61817
msec test #52 loops: 61726
msec test #53 loops: 61678
msec test #54 loops: 61724
msec test #55 loops: 61943
msec test #56 loops: 61844
msec test #57 loops: 61831
msec test #58 loops: 61769
msec test #59 loops: 61851

results with msec, then usec:

usec test #0 loops: 223231
usec test #1 loops: 223231
usec test #2 loops: 223233
usec test #3 loops: 223232
usec test #4 loops: 223233
usec test #5 loops: 223232
usec test #6 loops: 223233
usec test #7 loops: 223232
usec test #8 loops: 223233
usec test #9 loops: 223232
usec test #10 loops: 223233
usec test #11 loops: 223232
usec test #12 loops: 223233
usec test #13 loops: 223232
usec test #14 loops: 223233
usec test #15 loops: 223232
usec test #16 loops: 223233
usec test #17 loops: 223232
usec test #18 loops: 223233
usec test #19 loops: 223233
usec test #20 loops: 223232
usec test #21 loops: 223233
usec test #22 loops: 223232
usec test #23 loops: 223233
usec test #24 loops: 223232
usec test #25 loops: 223233
usec test #26 loops: 223232
usec test #27 loops: 223233
usec test #28 loops: 223232
usec test #29 loops: 223233
usec test #30 loops: 223232
usec test #31 loops: 223233
usec test #32 loops: 223232
usec test #33 loops: 223233
usec test #34 loops: 223232
usec test #35 loops: 223233
usec test #36 loops: 223233
usec test #37 loops: 223232
usec test #38 loops: 223233
usec test #39 loops: 223232
usec test #40 loops: 223233
usec test #41 loops: 223232
usec test #42 loops: 223233
usec test #43 loops: 223232
usec test #44 loops: 223233
usec test #45 loops: 223232
usec test #46 loops: 223233
usec test #47 loops: 223232
usec test #48 loops: 223233
usec test #49 loops: 223232
usec test #50 loops: 223233
usec test #51 loops: 223232
usec test #52 loops: 223233
usec test #53 loops: 223233
usec test #54 loops: 223232
usec test #55 loops: 223233
usec test #56 loops: 223232
usec test #57 loops: 223233
usec test #58 loops: 223232
usec test #59 loops: 223233
msec test #0 loops: 108712
msec test #1 loops: 111603
msec test #2 loops: 110294
msec test #3 loops: 109890
msec test #4 loops: 108944
msec test #5 loops: 108568
msec test #6 loops: 108525
msec test #7 loops: 108202
msec test #8 loops: 107600
msec test #9 loops: 107287
msec test #10 loops: 107210
msec test #11 loops: 106948
msec test #12 loops: 107111
msec test #13 loops: 106960
msec test #14 loops: 106843
msec test #15 loops: 106600
msec test #16 loops: 106194
msec test #17 loops: 106079
msec test #18 loops: 105930
msec test #19 loops: 105732
msec test #20 loops: 105752
msec test #21 loops: 105761
msec test #22 loops: 105586
msec test #23 loops: 105417
msec test #24 loops: 105531
msec test #25 loops: 105789
msec test #26 loops: 105575
msec test #27 loops: 105451
msec test #28 loops: 105336
msec test #29 loops: 105463
msec test #30 loops: 105213
msec test #31 loops: 105113
msec test #32 loops: 104812
msec test #33 loops: 104723
msec test #34 loops: 104685
msec test #35 loops: 104626
msec test #36 loops: 104379
msec test #37 loops: 104643
msec test #38 loops: 104333
msec test #39 loops: 104302
msec test #40 loops: 104011
msec test #41 loops: 104666
msec test #42 loops: 104333
msec test #43 loops: 104358
msec test #44 loops: 104018
msec test #45 loops: 104334
msec test #46 loops: 104029
msec test #47 loops: 103994
msec test #48 loops: 103705
msec test #49 loops: 104541
msec test #50 loops: 104405
msec test #51 loops: 104342
msec test #52 loops: 104068
msec test #53 loops: 104261
msec test #54 loops: 104096
msec test #55 loops: 103994
msec test #56 loops: 103763
msec test #57 loops: 104102
msec test #58 loops: 104118
msec test #59 loops: 103994

so order doesn't really impact usec, but it does impact msec, running first minute is fast, 2nd minute much slower, and still drags over time.

to a prior request, I moved the code to loop() just to see, here's the simplified version, just runs for a minute, only does msec, and waits till the end to print:


int Power = 11;
unsigned long lastmicro = 0;
unsigned long lastmilli = 0;
unsigned long tests = 0;
unsigned long loops = 0;
// we're going to test for ~1 minute
#define TESTS 60

unsigned long microsec[TESTS];  // loops counted/sec by usec
unsigned long millisec[TESTS]; // loops counted/sec by msec
unsigned long maxmicros = 0;    // max number of loops/sec by usec
unsigned long maxmillis = 0;    // max number of loops/sec by msec
unsigned long curcount;         // current counter (usec/msec)

void setup() {
  // pinMode(Power, OUTPUT);
  // digitalWrite(Power, HIGH);
  Serial.begin(57600);

  tests = 0;
}

void loop(void) {
  curcount = millis();
  loops++;
  if (curcount - lastmilli >= 1000) {
    // store results
    millisec[tests++] = loops;
    loops = 0;
    lastmilli += 1000;
    if (tests == TESTS)
      for (tests = 0; tests < TESTS; tests++) {
        Serial.print("msec test #");
        Serial.print(tests);
        Serial.print(" loops: ");
        Serial.println(millisec[tests]);
      }
  }
}

results were worse than setup:

msec test #0 loops: 79692
msec test #1 loops: 82433
msec test #2 loops: 81771
msec test #3 loops: 81552
msec test #4 loops: 81003
msec test #5 loops: 80789
msec test #6 loops: 80761
msec test #7 loops: 80617
msec test #8 loops: 80279
msec test #9 loops: 80098
msec test #10 loops: 80046
msec test #11 loops: 79887
msec test #12 loops: 79969
msec test #13 loops: 79895
msec test #14 loops: 79836
msec test #15 loops: 79711
msec test #16 loops: 79500
msec test #17 loops: 79439
msec test #18 loops: 79362
msec test #19 loops: 79219
msec test #20 loops: 79233
msec test #21 loops: 79247
msec test #22 loops: 79162
msec test #23 loops: 79059
msec test #24 loops: 79121
msec test #25 loops: 79273
msec test #26 loops: 79137
msec test #27 loops: 79073
msec test #28 loops: 78999
msec test #29 loops: 79103
msec test #30 loops: 78942
msec test #31 loops: 78891
msec test #32 loops: 78724
msec test #33 loops: 78678
msec test #34 loops: 78627
msec test #35 loops: 78614
msec test #36 loops: 78459
msec test #37 loops: 78613
msec test #38 loops: 78418
msec test #39 loops: 78409
msec test #40 loops: 78235
msec test #41 loops: 78631
msec test #42 loops: 78434
msec test #43 loops: 78451
msec test #44 loops: 78263
msec test #45 loops: 78426
msec test #46 loops: 78249
msec test #47 loops: 78260
msec test #48 loops: 78081
msec test #49 loops: 78541
msec test #50 loops: 78479
msec test #51 loops: 78447
msec test #52 loops: 78287
msec test #53 loops: 78398
msec test #54 loops: 78293
msec test #55 loops: 78246
msec test #56 loops: 78126
msec test #57 loops: 78327
msec test #58 loops: 78302
msec test #59 loops: 78249

I'm at a loss at this point, may look at switching to another IDE/language if I need to. These numbers are so much lower than expected too :frowning:

Thanks!
-B

18

I also removed that power pin setup, wasn't sure why the example code had it anyway :upside_down_face:

19

This topic was automatically closed 180 days after the last reply. New replies are no longer allowed.