Trouble with micros() [RESOLVED]

Hi all,

I'm warming up to Arduino by trying to implement an IR remote receiver, but there is something funny going on in my code that I cannot get a grip of. Specifically, the value output by micros() is less than the previous micros() call.

The output of my IR detector outputs looks like this:

And the remote commands can be found here:

Here's my full Arduino code to detect the starting pulse (4.5 ms). Int0 (LEVEL) ISR is used to initiate the process.

#define IR_PIN 2

volatile int state = 0;
boolean failed = false;

unsigned long logLastTime = 0;  // stores last output of micros()

// Onkyo RC-319S pulse-length coding signal spec (allowing ±10% timing error)
const unsigned long Tinit_min = 4050;
const unsigned long Tinit_max = 4950;

void setup()
{
  // start serial port at 9600 bps:
  Serial.begin(9600);

  pinMode(IR_PIN, INPUT);  // Set D2 to input to read GP1UM271:Vout

  // enable interrupt, which is triggered when D2 is low
  attachInterrupt(0, ir_level_isr, LOW);
}

void loop()
{
  unsigned long time, T;

  // get current time & time elapsed since last log time
  time = micros();
  T = time - logLastTime;
  
  switch (state)
  {
  case 1:  // waiting for the start pulse

    if (digitalRead(IR_PIN))  // LO->HI transition occurred
    {
      logLastTime = time;  // log current time
      state = 2;  // start measuring the start bit length
    }
    break;

  case 2:  // waiting for the end of the start pulse

    if (digitalRead(IR_PIN))  // no change
    {
      if (T > Tinit_max) // waited longer than expected pulse duration
      {
        failed = true;
      }
    }
    else  // HI->LO transition occurred
    {
      if (T < Tinit_min)  // start pulse ended too early
      {
        failed = true;
      }
      else  // within the tolerable duration, move on to first bit
      {
        Serial.println("Start pulse detected");               
        state = 0;
      }
    }
    break;
  }

  // IR signal detection failed, reset loop
  if (failed)
  {
    Serial.print(state,DEC);
    Serial.println(" IR Command Reception Failed");               

    state = 0;
    failed = false;
    Serial.print("[logLastTime: ");
    Serial.print(logLastTime,DEC);
    Serial.print(" | time: ");
    Serial.print(time, DEC);
    Serial.print(" | T: ");
    Serial.print(T, DEC);
    Serial.println("]");
  }
}

void ir_level_isr()
{
  if (state==0) state = 1;
}

Most of the time, this code works. But every once in a while, it fails to detect the starting pulse. I'm monitoring the IR detector output with a scope to make sure that the incoming signal waveform is clean all the time. And when it fails, the elapsed time is all messed up. For example, here's one of the failed message that I got:

2 IR Command Reception Failed
[logLastTime: 370711192 | time: 370710632 | T: 4294966736]

logLastTime is the time when the start pulse began (i.e., LO-to-HI transition last occurred) and time is the time observed in the current loop iteration (when the start pulse ended). But we have logLastTime>time... which doesn't make any sense.

If anyone can explain this behavior or know how to fix the problem, I'd love to hear it. (I'm thinking it must be an interrupt related issue, but has not yet nailed down the cause.)

Thanks,
Kesh

edit: logLastTime<time changed to logLastTime>time
edit 2: Problem resolved! Please see my Reply #8 for the corrected code.

What happens to your code in the case where micros() rolls over (after about 70 minutes)?

James,

Although I think you already know, the 70-min. roll-over is not the issue here (yet). It happens way too often for that.

That being said, I haven't run it long enough to know the effect of that. However, unsigned integer arithmetic should give me the correct difference (as long as the counter only rolls over once).

Kesh

The reason I asked is because of the values you showed in your debug output. However, I guess the value of T makes sense, given the subtraction of the other two variables.

I'm not seeing an obvious mistake or gotcha.

What about trapping any time you use use time or micros, to see if it is less than the previous value? Maybe pinpoint when it somehow becomes "less"?

"But we have logLastTime<time... "
But you don't:
logLastTime: 370711192
time: 370710632

you have current time which is earlier, hence the elapsed time is hosed.

Not seeing how that is happening with the code you have listed tho.

Why do this:

  attachInterrupt(0, ir_level_isr, LOW);

Why not put an interrupt on change? Or not even use interrupts as you are looping looking for level changes anyway? My guess is that you are spending too much time in the ISR, and thus the timer interrupt is not always being caught. If the timer interrupt is not processed it doesn't increment the overflow count. So this is how the timer could go backwards...

micros() returns, effectively:

timer0_overflow_count * microseconds_per_overflow + extra_stuff_since_last_interrupt

Now the "extra stuff" is always changing, that is built into the timer itself, and doesn't rely on interrupts. So if "extra stuff" was high initially, and then became low, but we missed an interrupt, the time would go backwards. eg. (made-up-figures):

overflow_count = 42
extra = 99
microseconds_per_overflow = 1000

returned time = 42 * 1000 + 99 == 4299

Then, missing an interrupt:

overflow_count = 42   (should be 43)
extra = 10
microseconds_per_overflow = 1000

returned time = 42 * 1000 + 10 == 4210   (should be 4310)

Personally I wouldn't use a LOW interrupt. I am presuming that will fire a lot. It detects the line is low, fires the interrupt, you process it (which re-arms the interrupt), it fires again, etc. All during that big long low pulse at 0ms on your graphic. Meanwhile the clock timer is hard-pressed to get its interrupts processed.

Thanks guys for your responses!

@James - I tried that but serial port is too slow to keep up with IR data flow

@CR - oops. Fixed the original text. thx for point that out.

@Nick - You are absolutely right. Changed INT0 trigger to FALLING, and the problem went away. Yay!! Also, thanks for explaining the in-depth mechanism of micros().

Now, you also suggested

not even use interrupts

The reason for it being interrupt activated is that later I want to wake up the uC with the remote... Oh, that's why I decided to use the LOW trigger. The datasheet (p.39, Table 9-1, Note 3) only LEVEL INT0 can wake uC up.

Maybe I need to use one of PCINTs instead. Would that work?

Well, detach the interrupt in the ISR*. That calms it down. Then reattach it later. Bear in mind the discussion in another thread about how interrupts are remembered in advance.

(Edit) *Or change it to falling.

(Edit#2) I don't think the "low" interrupts are remembered, I could be wrong.

Yep, detaching then reattaching INT0 LEVEL ISR works.

Here's the resolved code:

#include <avr/sleep.h>

#define IR_PIN 2

volatile int state = 0;
boolean reset = false;
boolean failed = false;

unsigned long logLastTime = 0;  // stores last output of micros()

// Onkyo RC-319S pulse-length coding signal spec (allowing ±10% timing error)
const unsigned long Tinit_min = 4050;
const unsigned long Tinit_max = 4950;

void setup()
{
  // start serial port at 9600 bps:
  Serial.begin(9600);

  // Set D2 to input to read GP1UM271:Vout
  pinMode(IR_PIN, INPUT);  

  // enable interrupt, which is triggered when D2 is low
  attachInterrupt(0, ir_level_isr, LOW);

  // to demonstrate waking up from power-down state
  set_sleep_mode(SLEEP_MODE_PWR_DOWN);
  sleep_mode();
}

void loop()
{
  unsigned long time, T;

  // get current time & time elapsed since last log time
  time = micros();
  T = time - logLastTime;
  
  switch (state)
  {
  case 1:  // waiting for the start pulse

    if (digitalRead(IR_PIN))  // LO->HI transition occurred
    {
      logLastTime = time;  // log current time
      state = 2;  // start measuring the start bit length
    }
    break;

  case 2:  // waiting for the end of the start pulse

    if (digitalRead(IR_PIN))  // no change
    {
      if (T > Tinit_max) // waited longer than expected pulse duration
      {
        failed = true;
      }
    }
    else  // HI->LO transition occurred
    {
      if (T < Tinit_min)  // start pulse ended too early
      {
        failed = true;
      }
      else  // within the tolerable duration, move on to first bit
      {
        Serial.println("Start pulse detected");               
        reset = true;
      }
    }
    break;
  }

  // IR signal detection failed, reset loop
  if (failed)
  {
    Serial.print(state,DEC);
    Serial.println(" IR Command Reception Failed");               

    reset = true;
    failed = false;

    Serial.print("[logLastTime: ");
    Serial.print(logLastTime,DEC);
    Serial.print(" | time: ");
    Serial.print(time, DEC);
    Serial.print(" | T: ");
    Serial.print(T, DEC);
    Serial.println("]");
  }

  if (reset)
  {
   // reset the IR receiver state
    state = 0;

    // clear the reset flag
    reset = false;

    // re-enable the interrupt
    attachInterrupt(0, ir_level_isr, LOW);
  }
}

void ir_level_isr()
{
  // disable ISR
  detachInterrupt(0);
  
  // start IR decoding
  state = 1;
}

@Nick - I searched for "interrupts remembered in advance" but couldn't find anything on it. Would you post a link for the thread with this discussion?

Thanks

http://arduino.cc/forum/index.php/topic,59217.0.html