differing results from micros() in loop() and interrupt

Using Arduino Programming Questions
#1

I put together a simple app to read IR remote pulses with a Uno and an IR receiver. The receiver data line is connected to Pin2. I have an interrupt set for Pin 2 state changes. When the interrupt hits I look at the Pin state and grab the current usec count from micros() to calculate the pulse time. In my loop() I want to check if we’ve gone a while since the last Pin2 state change as this would signal the end of the IR data from the. I grab the current usec count from micros() and compare it to the last usec count grabbed in the interrupt routine. The problem I am having is occasionally the usec count returned from micros() in the loop() function is smaller that the last one received in the interrupt routine. It’s not a wraparound to 0 and I’ve debugged enough with Serial.print() to believe I’m not crazy. I’m getting the same results in 1.0 and 1.5.6-r2.

#include <limits.h>

int          LEDPin = 13;
volatile int LEDState = LOW; 

enum IRReadState
{
  IR_IDLE = 0,
  IR_READING_PULSE,
  IR_READING_GAP
} ;

typedef struct _IRPulse
{
	// start and end are for debugging only
  unsigned long start;
  unsigned long end;

  unsigned int  length;
  bool          active;
} IRPulse;
  
volatile enum IRReadState	s_currentReadState = IR_IDLE;
volatile enum IRReadState	s_lastReadState = IR_IDLE;

volatile unsigned long		s_currentPulseStart = 0;

const unsigned int				s_sizePulses = 100;
IRPulse										s_Pulses[s_sizePulses];
volatile unsigned int			s_idxNextPulse = 0;

volatile unsigned int     s_printError = 0;

// copied from libraries
extern volatile unsigned long timer0_overflow_count;

unsigned long _micros() 
{
	unsigned long m;
	uint8_t oldSREG = SREG, t;
	
	cli();
	m = timer0_overflow_count;
#if defined(TCNT0)
	t = TCNT0;
#elif defined(TCNT0L)
	t = TCNT0L;
#else
	#error TIMER 0 not defined
#endif

  
#ifdef TIFR0
	if ((TIFR0 & _BV(TOV0)) && (t < 255))
		m++;
#else
	if ((TIFR & _BV(TOV0)) && (t < 255))
		m++;
#endif

	SREG = oldSREG;
	
	return ((m << 8) + t) * (64 / clockCyclesPerMicrosecond());
}

// calculate a time difference taking into account possible wraparound
unsigned int diffTime( unsigned long i_endTime, unsigned long i_startTime )
{
	if( i_startTime > i_endTime )
		return (unsigned int) (ULONG_MAX - i_startTime + i_endTime);
	else
		return (unsigned int) (i_endTime - i_startTime);
}

void setup()
{
  // set up LED for flashing
  pinMode( LEDPin, OUTPUT );
  
  // set up an interrupt for IR Receiver on Pin 2
  // IR Receiver must be on Pin 2. Uno only supports
  // interrupts from Pin 2 & 3
  attachInterrupt( 0, Pin2Change, CHANGE );

  s_currentPulseStart = _micros();
  
  // set up Serial for spew
  Serial.begin( 115200 );
  Serial.println( "Ready to record IR signals." );
}

void loop()
{
	static unsigned int lastPulseCount = 0;
	static unsigned int idxCurrentCommand = 0;

	unsigned int currentPulseCount = s_idxNextPulse;

	// Print a message that the interrupt is actually doing it's job
	if( lastPulseCount != currentPulseCount )
	{
		Serial.print( "Pulse Count: " );
		Serial.print( currentPulseCount );
		Serial.println( "." );

		lastPulseCount = currentPulseCount;
	}

	// If we've received pulses and are in a gap state we may be done.
	// Look for a long gap
	if( (idxCurrentCommand < s_idxNextPulse)  &&  (s_currentReadState == IR_READING_GAP) )
	{
		unsigned long current = _micros();
		unsigned long start = s_currentPulseStart;

		unsigned int delay = diffTime( current, start );

		if( delay > 32767 )
		{
			/*
			Serial.print( "I: " );
			Serial.print( s_idxNextPulse );
			Serial.print( " C: " );
			Serial.print( current );
			Serial.print( " S: " );
			Serial.print( start );
			Serial.print( " RS: " );
			Serial.print( s_currentReadState );
			Serial.print( " LRS: " );
			Serial.print( s_Pulses[s_idxNextPulse - 1].active );
			Serial.println( "." );
			*/
			if( s_idxNextPulse < s_sizePulses )
			{
      	s_Pulses[s_idxNextPulse].start = start;
				s_Pulses[s_idxNextPulse].end = current;
				s_Pulses[s_idxNextPulse].length = 32767;
				s_Pulses[s_idxNextPulse].active = false;
				s_idxNextPulse++;
			}

			s_currentReadState = IR_IDLE;
				
			unsigned int commandEndPulse = s_idxNextPulse;

			Serial.flush();
			
			// Print out the pulses in this command
			for( unsigned int i = idxCurrentCommand; i < commandEndPulse; i++ )
			{
				Serial.print( "Pulse[" );
				Serial.print( i );
				if( s_Pulses[i].active )
					Serial.print( "]:  On " );
				else
					Serial.print( "]: Off " );

				Serial.print( s_Pulses[i].length );
				Serial.print( " usec." );

				Serial.print( " E: " );
				Serial.print( s_Pulses[i].end );
				Serial.print( " S: " );
				Serial.print( s_Pulses[i].start );
				Serial.println( "." );

			}

			Serial.flush();
			
			idxCurrentCommand = commandEndPulse;
		}
	}
	else

	if( s_printError > 0 )
	{
		Serial.print( "State change error: " );
		Serial.print( s_printError );
		Serial.println( "." );
    
		s_printError = 0;
	}
}

// Our interrupt that detects state changes
void Pin2Change()
{
  const bool signalReceived = !(PIND & _BV(2));
   
  switch( s_currentReadState )
  {
  case IR_IDLE:
    if( signalReceived )
    {
      s_currentPulseStart = _micros();
      s_currentReadState = IR_READING_PULSE;
    }
    else
    {
      s_printError = 1;
    }
    
    break;
    
  case IR_READING_PULSE:
    if( !signalReceived )
    {
		if( s_idxNextPulse < s_sizePulses )
		{
			s_Pulses[s_idxNextPulse].start = s_currentPulseStart;
			s_Pulses[s_idxNextPulse].end = _micros();
			s_Pulses[s_idxNextPulse].length = _micros() - s_currentPulseStart;
			s_Pulses[s_idxNextPulse].active = true;
			s_idxNextPulse++;
		}
      
		s_currentPulseStart = _micros();
		s_currentReadState = IR_READING_GAP;
    }
    else
		s_printError = 2;
    
    break;
    
  case IR_READING_GAP:
	if( signalReceived )
	{
		if( s_idxNextPulse < s_sizePulses )
		{
			s_Pulses[s_idxNextPulse].start = s_currentPulseStart;
			s_Pulses[s_idxNextPulse].end = _micros();

			s_Pulses[s_idxNextPulse].length = _micros() - s_currentPulseStart;
			s_Pulses[s_idxNextPulse].active = false;
			s_idxNextPulse++;
		}
      
		s_currentPulseStart = _micros();
		s_currentReadState = IR_READING_PULSE;
    }
    else
		s_printError = 3;

	break;
  }
}

Thanks,

Joe

#2

What are the chances that the IRQ is changing data when you don't expect?

Other than that, I don't know where to begin except to say that your IRQ looks fat and Serial.print has an interrupt of its own and blocks until its buffer is clear.

You seem to have timing problems that may stem from what you're trying to do as much as how. It looks over-complicated but I'm not diving in to verify that.

#3

If I remember correctly mivros counts in 4 not ones. And yes I can see a way that the micros in loop is smaller than the one in the ISR.

		unsigned long current = _micros();
		unsigned long start = s_currentPulseStart;

		unsigned int delay = diffTime( current, start );

Think through this bit of your code and keep in mind that you have two ISR running.

By the way drop the dead Serial.flush() it just waits fro the TX buffer to empty.

Mark

#4

When accessing volatile variables bigger than a single byte in the main context, you need to disable interrupts around the access. The preferred technique is to disable, copy the volatile variable to a temporary local, and immediately re-enable. Otherwise you can end up with the interrupt changing the volatile variable in the middle of the access, so that your main context code sees some bytes from the old value and some from the new value.

#5

Thanks everone.

holmes, as soon as I looked at those few lines I saw the problem and thanks PeterH for the info. I have it working now. Ironically while looking around for a solution I found an already written library that does what I want.

Joe

#6