Why does this simple code fail?

I've been banging my head on this for a week! I wrote some simple timer code to turn something on and off on an interval. I put in code to handle the millis() rollover. The trouble is that I hit the rollover code much too quickly.

lastMS should never be greater than currentMS unless the timer has rolled over to zero. The code ends up catching lastMS getting ahead of currentMS by around 300 ms, which shouldn't be possible.

I figure I'm either missing something very simple or I've run in to some issue with the Arduino.

By moving the code around, I can cause the false rollover to happen sooner or later. Anywhere from the first iteration to around 10 minutes.

This code fails immediately. What it should do is send "valve on" and "valve off" over the serial port for 9+ hours and then send "Rollover" once. What it does it send "Rollover" right away.

int  valve1Pin = 13;                // LED connected to digital pin 13

int          valve1Value = LOW;                // previous value of the LED
unsigned long          valve1Duration = 2000;
unsigned long          valve1Interval = 10000L;
unsigned long          counterMS = 0;
unsigned long          lastMS = 0;
unsigned long          currentMS = 0;

void UpdateClock( int button )
{
  short  doneOnce = 0;

  currentMS = millis();
  if (currentMS >= lastMS)
  {
    counterMS += (currentMS - lastMS);
    lastMS = currentMS;

    if (!valve1Value && (counterMS > valve1Interval))
    {
      while (counterMS > valve1Interval)
      {
        if (doneOnce)
        {
          Serial.println( "Interval behind" );
          delay(500);
        }
        doneOnce = true;
        counterMS = counterMS - valve1Interval;
      }
      valve1Value = HIGH;
      digitalWrite( valve1Pin, HIGH );
      Serial.println( "Valve On" );
    }
    else if (valve1Value && (counterMS > valve1Duration))
    {
      while (counterMS > valve1Duration)
      {
        if (doneOnce)
        {
          Serial.println( "Duration behind" );
          delay( 500 );
        }
        doneOnce = true;
        counterMS = counterMS - valve1Duration;
      }
      valve1Value = LOW;
      digitalWrite( valve1Pin, LOW );
      Serial.println( "Valve Off" );
    }
  }
  else if (currentMS < lastMS)
  {
//    char  tempStr[50];
//    char  tempStr1[75];
    
    counterMS += (currentMS + (0x020C49B9 - lastMS));
    Serial.println( "Rollover!" );
//     strcpy( tempStr, "cur " );
//    ltoa( currentMS, tempStr1, 10 );
//    strcat( tempStr, tempStr1 );
//    strcat( tempStr, " last " );
//    ltoa( lastMS, tempStr1, 10 );
//    strcat( tempStr, tempStr1 );
//    Serial.println( tempStr );
   delay(3000);
  }
}


void setup()
{
  Serial.begin(9600);
  pinMode( valve1Pin, OUTPUT );      // sets the digital pin as output
  
  lastMS = millis();
}

void loop()
{  
  // update clock
  UpdateClock( 0 );
}

What am I doing wrong????

As an alternative to trying to make the old millis code behave, you may instead want to change the code in wiring.c so it rolls over cleanly. Here is the code that mellis is proposing to use in the next release of the Arduino.

SIGNAL(SIG_OVERFLOW0)
{
// timer 0 prescale factor is 64 and the timer overflows at 256
timer0_clock_cycles += 64UL * 256UL;
PORTD |= 1 << 4;
while (timer0_clock_cycles > clockCyclesPerMicrosecond() * 1000UL) {
timer0_clock_cycles -= clockCyclesPerMicrosecond() * 1000UL;
timer0_millis++;
}
}

unsigned long millis()
{
unsigned long m;
uint8_t oldSREG = SREG;

cli();
m = timer0_millis;
SREG = oldSREG;
return m;
}

I appreciate your quick reply. I'm also looking forward to the improvement of the millis() overflow. I don't think this is an overflow problem however. I think my overflow code just happens to catch the problem. I've used this overflow catching code in another project with very good results.

My question is how does lastMS get ahead of currentMS when lastMS is set directly from currentMS?

Other than overflow, will millis() ever return a lower value than last time?

If I comment in the debugging code in the overflow section to send the values of currentMS and lastMS out the serial port, the program no longer fails immediately. It takes around 150 seconds before catching a false overflow. Just now I got 150208 as currentMS and 150469 as lastMS.

How did currentMS get behind lastMS by 261ms?

How is it that adding 7 lines of debugging code that isn't even executed right away completely changes the way the code behaves? Am I using uninitialized memory somewhere that I'm not aware of? That would explain this weirdness.

It sounds to me like you could be experiencing a problem due to millis()'s unsafe use of the timer0 overflow interrupt. Adding seven lines of debugging code just changes the timing, which alters when the unsafe use causes problems. If you ever see something strange like this, it's a good bet that you're either having an interrupt-generated bug, or a stack overflow problem. It can be very difficult to track down because every print statement you add to try to debug the situation ends up changing the bug! I once had a program like this where I "fixed" the bug by trying to print information about variable states to the LCD. At any rate, I explain more about the specific nature of millis()'s unsafe interrupt use in this thread:

http://www.arduino.cc/cgi-bin/yabb2/YaBB.pl?num=1210889307

The more often you call millis(), the greater the chance that it will get interrupted in a bad way, right in the middle of a read-modify-write cycle of the overflow interrupt counter, which in turn will cause it to have a corrupted value that could trigger your overflow code. Try making one simple change to your program: immediately before every millis() call put cli(); and immediately after put sei();. This will disable interrupts while millis() is being executed and then re-enable them after. For example:

cli();
lastMS = millis();
sei();
...
cli();
currentMS = millis();
sei();

Can you tell me if doing this affects your problem in any way? If not, the bug is perhaps even more exotic than this.

  • Ben

THANK YOU! You have returned my sanity. Your suggested fix seems to have eliminated the early rollover I was getting. I added your fix to the variant of my code that was breaking immediately and it has been running wonderfully for the past hour with no troubles.

I need to read your other thread and understand this a bit more, but your short explanation makes sense with what I've been seeing. I was also having trouble with variables not getting the right initial value now and again. All of this would be explained by getting interrupted during a memory write. Also the more I simplified my code, the worse it got because it was calling millis() more and more and more. My previous program didn't exhibit this problem because it had a lot more other things going on. Checking for buttons being pushed, updating an LED in a complex pattern, etc. So it called millis() much less often.

I am no stranger to programming and was going nuts because I could not pin this down! I did not think about interrupts as a possible cause.

Yea! Now I can finish the code and stuff a transistor in to drive a relay and then things can really get exciting.

I'm very glad to hear that it worked! Good luck with the rest of your program.

  • Ben