Longer processing time on initial run through if...else?

I was messing around with millis(), increments, and if…else when I noticed something interesting. It appears that the initial run through an if…else takes longer to process/compute than subsequent runs, when the if…else conditions remain true through each repeated loop. If the conditions are not true for a loop, then the next time they are true, it takes longer again.

The code is a basic button state detection and increment counter with some ramping on the increment speed, the longer the button is held.

long holdTime = 0;        // stores time elapsed since the button was pressed
unsigned long pressTime = 0; // stores the time at which the button was pressed
unsigned long loopStartTime = 0;
long loopCycleTime = 0;

// this constant won't change:
const int  buttonPin = 13;    // the pin that the pushbutton is attached to

// Variables will change:
int buttonPushCounter = 0;   // counter for the number of button presses
int buttonState = 0;         // current state of the button
int lastButtonState = 0;     // previous state of the button

void setup() {
  // initialize the button pin as a input:
  pinMode(buttonPin, INPUT);
  // initialize serial communication:
  Serial.begin(9600);
}
void loop() {
  loopStartTime = millis();
  buttonState = digitalRead(buttonPin);
  if (buttonState != lastButtonState) {
    if (buttonState == HIGH) {
      pressTime = millis();
      buttonPushCounter++;
      Serial.println("on");
      Serial.print("number of button pushes: ");
      Serial.println(buttonPushCounter);
    } else {
      Serial.println("off");
    }
    delay(50);
  }
  holdTime = (millis() - pressTime);
  if (buttonState == HIGH && buttonState == lastButtonState) {
    if (holdTime < 700) {
    }
    else if (holdTime >= 700 && holdTime <= 2500) {
      buttonPushCounter++;
      Serial.println("on");
      Serial.print("buttonPushCounter: ");
      Serial.println(buttonPushCounter);
      delay(150);
    }
    else if (holdTime > 2500) {
      buttonPushCounter++;
      Serial.println("on");
      Serial.print("buttonPushCounter: ");
      Serial.println(buttonPushCounter);
      delay(90);
    } else {
      Serial.println("off");
    }
  }
  lastButtonState = buttonState;
  loopCycleTime = (millis() - loopStartTime);
  Serial.print("loopCycleTime: ");
  Serial.println(loopCycleTime);
}

It seems to take about 30ms longer on the first time through the if…else. Strange.

I decided to increase the baud to 115200 for more accuracy. The millis() difference decreased on the first time through the if…else.

Maybe it’s an issue with the amount of data sent to serial? Possibly a cache thing?If the baud rate is a bottle neck, then it would stand that the loopCycleTime would change inverse to baud.

Possibly a cache thing?

Anyone have any idea why this happens? I’d be really interested to find out, and I’m trying to avoid going down that rabbit hole of testing on my day off.

//9600 baud
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
on
number of button pushes: 1
loopCycleTime: 84 //84 - delay(50) = 34
off
loopCycleTime: 50
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
on
number of button pushes: 2
loopCycleTime: 83 //83 - delay(50) = 33
loopCycleTime: 0
loopCycleTime: 0
off
loopCycleTime: 51
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
on
number of button pushes: 3
loopCycleTime: 83  //83 - delay(50) = 33
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
on
buttonPushCounter: 4
loopCycleTime: 177 //177 - delay(150) = 27
on
buttonPushCounter: 5
loopCycleTime: 150 //150 - delay(150) = 0
on
buttonPushCounter: 6
loopCycleTime: 149
on
buttonPushCounter: 7
loopCycleTime: 150
on
buttonPushCounter: 8
loopCycleTime: 149
on
buttonPushCounter: 9
loopCycleTime: 150
on
buttonPushCounter: 10
loopCycleTime: 150
on
buttonPushCounter: 11
loopCycleTime: 151
on
buttonPushCounter: 12
loopCycleTime: 150
on
buttonPushCounter: 13
loopCycleTime: 151
on
buttonPushCounter: 14
loopCycleTime: 150
on
buttonPushCounter: 15
loopCycleTime: 151
on
buttonPushCounter: 16 // child if changed true, but parent remained the same
loopCycleTime: 90 //90 - delay(90) = 0
on
buttonPushCounter: 17
loopCycleTime: 90
on
buttonPushCounter: 18
loopCycleTime: 90
on
buttonPushCounter: 19
loopCycleTime: 91
on
buttonPushCounter: 20
loopCycleTime: 90
on
buttonPushCounter: 21
loopCycleTime: 91
on
buttonPushCounter: 22
loopCycleTime: 90
on
buttonPushCounter: 23
loopCycleTime: 90
on
buttonPushCounter: 24
loopCycleTime: 90
on
buttonPushCounter: 25
loopCycleTime: 90
on
buttonPushCounter: 26
loopCycleTime: 91
on
buttonPushCounter: 27
loopCycleTime: 90
on
buttonPushCounter: 28
loopCycleTime: 90
on
buttonPushCounter: 29
loopCycleTime: 91
on
buttonPushCounter: 30
loopCycleTime: 90
off
loopCycleTime: 50
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
//115200 baud
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
on
number of button pushes: 1
loopCycleTime: 52
loopCycleTime: 0
//~30 lines removed for readability
loopCycleTime: 0
off
loopCycleTime: 50
loopCycleTime: 0
//~60 lines
loopCycleTime: 0
on
number of button pushes: 2
loopCycleTime: 53
//~25 lines
loopCycleTime: 0
off
loopCycleTime: 50
loopCycleTime: 0
//~70 lines
loopCycleTime: 0
on
number of button pushes: 3
loopCycleTime: 52
loopCycleTime: 0
//~400 lines
loopCycleTime: 0
on
buttonPushCounter: 4
loopCycleTime: 153
on
buttonPushCounter: 5
loopCycleTime: 151
on
buttonPushCounter: 6
loopCycleTime: 150
on
buttonPushCounter: 7
loopCycleTime: 151
on
buttonPushCounter: 8
loopCycleTime: 150
on
buttonPushCounter: 9
loopCycleTime: 151
on
buttonPushCounter: 10
loopCycleTime: 150
on
buttonPushCounter: 11
loopCycleTime: 151
on
buttonPushCounter: 12
loopCycleTime: 150
on
buttonPushCounter: 13
loopCycleTime: 151
on
buttonPushCounter: 14
loopCycleTime: 149
on
buttonPushCounter: 15
loopCycleTime: 150
on
buttonPushCounter: 16
loopCycleTime: 90
on
buttonPushCounter: 17
loopCycleTime: 91
on
buttonPushCounter: 18
loopCycleTime: 90
on
buttonPushCounter: 19
loopCycleTime: 91
on
buttonPushCounter: 20
loopCycleTime: 90
on
buttonPushCounter: 21
loopCycleTime: 90
on
buttonPushCounter: 22
loopCycleTime: 90
on
buttonPushCounter: 23
loopCycleTime: 90
on
buttonPushCounter: 24
loopCycleTime: 90
on
buttonPushCounter: 25
loopCycleTime: 90
on
buttonPushCounter: 26
loopCycleTime: 90
on
buttonPushCounter: 27
loopCycleTime: 90
on
buttonPushCounter: 28
loopCycleTime: 92
on
buttonPushCounter: 29
loopCycleTime: 90
on
buttonPushCounter: 30
loopCycleTime: 91
on
buttonPushCounter: 31
loopCycleTime: 90
on
buttonPushCounter: 32
loopCycleTime: 91
on
buttonPushCounter: 33
loopCycleTime: 90
on
buttonPushCounter: 34
loopCycleTime: 91
off
loopCycleTime: 51
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0

Tried this at 1200 baud to see if the the previously mentioned inverse relationship theory would hold true. It didn't. Now I'm even more confused.

//1200 baud
loopCycleTime: 0
loopCycleTime: 0
on
number of button pushes: 1
loopCycleTime: 316
off
loopCycleTime: 91
loopCycleTime: 0
loopCycleTime: 0
on
number of button pushes: 2
loopCycleTime: 317
off
loopCycleTime: 91
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
loopCycleTime: 0
on
number of button pushes: 3
loopCycleTime: 317
loopCycleTime: 0
loopCycleTime: 0
on
buttonPushCounter: 4
loopCycleTime: 366
on
buttonPushCounter: 5
loopCycleTime: 366
on
buttonPushCounter: 6
loopCycleTime: 366
on
buttonPushCounter: 7
loopCycleTime: 367
on
buttonPushCounter: 8
loopCycleTime: 367
on
buttonPushCounter: 9
loopCycleTime: 308
on
buttonPushCounter: 10
loopCycleTime: 316
on
buttonPushCounter: 11
loopCycleTime: 315
on
buttonPushCounter: 12
loopCycleTime: 314
on
buttonPushCounter: 13
loopCycleTime: 315
on
buttonPushCounter: 14
loopCycleTime: 315
on
buttonPushCounter: 15
loopCycleTime: 316
on
buttonPushCounter: 16
loopCycleTime: 314
on
buttonPushCounter: 17
loopCycleTime: 315
on
buttonPushCounter: 18
loopCycleTime: 315
on
buttonPushCounter: 19
loopCycleTime: 315
on
buttonPushCounter: 20
loopCycleTime: 316
on
buttonPushCounter: 21
loopCycleTime: 315
on
buttonPushCounter: 22
loopCycleTime: 315
off
loopCycleTime: 91
loopCycleTime: 0
loopCycleTime: 0

You're indeed overflowing the serial buffer. Below a stripped version of your code that only prints loopCycleTime if it exceeds 20ms; without it, it exhibits the same behaviour as you described.

void loop()
{
  loopStartTime = millis();
  buttonState = digitalRead(buttonPin);
  if (buttonState != lastButtonState)
  {
    if (buttonState == ISPRESSED)
    {
      pressTime = millis();
      buttonPushCounter++;
      Serial.println("on");
      Serial.print("number of button pushes: ");
      Serial.println(buttonPushCounter);
    }
    else
    {
      Serial.println("off");
    }
    delay(50);
  }

  lastButtonState = buttonState;
  loopCycleTime = (millis() - loopStartTime);
  if (loopCycleTime >= 20)
  {
    Serial.print("loopCycleTime: ");
    Serial.println(loopCycleTime);
  }
}

NOTE: because my buttons use the internal pull-up, I use ISPRESSED (which is defined as LOW); you can change it back to HIGH for your code. I also used pin 2 instead of 13.

The result gives the expected 50 ms.