Micros() returning bad data in interrupt

I'm developing code for a motor controller that we've constructed from scratch. In order for the motor controller to operate correctly, I need to calculate the realtime velocity of the motor. This is done by recording the time between ticks of the encoders.

During operation, the velocity seems to be all over the place. I narrowed down the issue to the times that were being returned by the micros() function in the interrupt being triggered by the encoders.

In an effort to debug, I created the following code to output all of the times that were being recorded when the interrupt fired.

#define MAX_POWER 255

//
// Pin definitions
//
#define ENCODER_A 2
#define ENCODER_B 3

#define MOTOR_CURRENT_1 A0
#define MOTOR_CURRENT_2 A1
#define MOTOR_VOLTAGE   A2

#define MOTOR_DIRECTION 10
#define MOTOR_PWM       11
#define MOTOR_FAULT     12
#define MOTOR_ENABLE    13

//
// Buffer
//
volatile uint16_t i = 0;
const uint16_t MAX_RECORDS = 200;
volatile unsigned long time[MAX_RECORDS];

void setup(){
  Serial.begin(115200);

  // Pin setup
  pinMode(MOTOR_DIRECTION, OUTPUT);
  pinMode(MOTOR_PWM      , OUTPUT);
  pinMode(MOTOR_ENABLE   , OUTPUT);
  pinMode(MOTOR_FAULT    , INPUT );
  pinMode(ENCODER_A      , INPUT );
  pinMode(ENCODER_B      , INPUT );

  attachInterrupt(0, tick, RISING);
  
  digitalWrite(MOTOR_ENABLE, HIGH);
  analogWrite(MOTOR_PWM, MAX_POWER);
}

void tick(){
  if(i == MAX_RECORDS) return;

  time[i++] = micros();
}

void loop(){
  if(i == MAX_RECORDS){
    while(i--) Serial.println(time[i]);
  }
}

Below is a snippet of the resulting output. You'll notice that, though the times are trending upwards, it's not a straight linear progression. I'm using the latest version of the Arduino IDE (1.0.5) on OSX 10.8.4. Any idea what's going on here, or, more importantly, how to fix it? Suffice it to say, this is extremely frustrating.

12696792
12695156
12693524
12691880
12698436
12690224
12688580
12700092
12686940
12685308
12683664
12701736
12682008
12680364
12703368
12678728
12705004
12677096
12706648
12675452
12708308
12673796
12709948
12672152
12711580
12670516
12713216
12668880
12714860
12667240
12716516
12665580
12718160
12663936
12719792
12662300
12721428
12723076
12660668
12724732
12659024
12726376
12657368
12728008
12655724
12729644
12654084
12731288
12652452
12732944
12650808
12734588
12649152
12736220
12647508
12737856
12645872
12739504
12644240
12741160
12642596
12742804
12640940
12744436
12639296
12746072
12747716
12637660
12749372
12636028
12751016
12634384
12752648
12632728
12754284
12631080
12755932
12629444
12757588
12627812
12759232
12626168
12760864
12624512
12762500
12622868
12764144
12621232
12765800
12619600
12767444
12617956
12769076
12616300
12770716
12772364
12614656
12774016
12613016
12775660
12611384
12777292
12609740
12778928
12608084
12780572
12606440
12782228
12604804
12783876
12603172
12785504
12601528
12787140
12599872
12788784
12598228
12790440
12596592
12792084
12594956
12793716
12795356
12593312
12797000
12591656
12798656
12590012
12800300
12588376
12801932
12586740
12803568
12585096
12805212
12583440
12806868
12581796
12808512
12580160
12810144
12578524
12811784
12576880
12813428
12575224
12815084
12573580
12816728
12571944
12818360
12820000
12570312
12821644
12568664
12823296
12567008
12824944
12565364
12826576
12563728
12828212
12562092
12829860
12560448
12831512
12558792
12833156
12557148
12834788
12555512
12836428
12553880
12838072
12552232
12839728
12550576
12841372
12548932
12843004
12844640
12547296
12846288
12545664
12847944
12544016
12849588
12542360
12851220
12540716
12852856
12539080
12854500
12537448
12856156
12535804
12857800
12534148
12859440
12532500
12861072
12530864
12862716
12529232
12864372
12527588
12866016
12525932
12867648
12869288
12524284
12870932
12522648
12872588
12521016
12874232
12519372
12875864
12517716
12877504
12516068
12879148
12514432
12880804
12512800
12882448
12511156
12884080
12509500
12885720
12507856
12887364
12506216
12889020
12504584
12890664
12502940
12892296
12893932
12501284
12895576
12499640
12897232
12498004
12898880
12496372
12900512
12494728
12902148
12493072
12903792
12491424
12905448
12489788
12907092
12488156
12908724
12486512
12910360
12484856
12912004
12483212
12913660
12481576
12915308
12479944
12916940
12918576
12478300
12920220
12476644
12921876
12475000
12923520
12473360
12925152
12471732
12926792
12470088
12928436
12468432
12930092
12466788
12931736
12465152
12933368
12289412
12935004
12287756
12936648
12286112
12938304
12284476
12939948
12282844
12941584
12943220
12281200
12944864
12279544
12946520
12277900
12948164
12276264
12949796
12274632
12951432
12272988
12953076
12271332
12954732
12269688
12956376
12268052
12958008
12266420
12959648
12264776
12961292
12263120
12962948
12261476
12964592
12259840
12966224
12967860
12258208
12969504
12256564
12971160
12254908
12972804
12253264
12974436
12251628
12976072
12249996
12977716
12248352
12979376
12246696
12981016

Printing deltas might make it easier to see what is going on.
Posting a schematic might also help.

I narrowed down the issue to the times that were being returned by the micros() function in the interrupt being triggered by the encoders.

That may or may not be true. What is true is that your debug code fails to prove that micros is a problem. There are at least three problems with your debug code...

  1. You are printing values off the tail of the array and adding values to the tail of the array. If an interrupt occurs during printing, the values will be out of order.

  2. The elements of time are multi-byte which means they have to be protected from access (interrupts disabled when reading an element in loop). Technincally, i has to also be protected but, because the values are kept below 256, there will not be a symptom.

  3. Modifying i in loop has to be protected (interrupts disabled).

I suggest you find and use ring-buffer code that is known to work correctly.

Coding error:

The problem is that loop() is counting 'i' down to zero and as soon as 'i' goes below MAX_RECORDS your ISR will start trying to count it forward again, filling the array with newer data. Try detaching the interrupt before you start counting 'i' down.

Edit: That's how you managed to get 342 samples from a 200 element array. :slight_smile:

If you sort the samples in ascending order you get deltas all between 1628 and 1660.

Or, more simply, use a different counter

Coding Badly nailed it. I'm really not used to coding embedded systems and don't fully understand the intricacies of reading/writing registers and interrupts.

As for the point about new data in the array, you're right, I'm technically going back in time every 200 entries, but each of those 200 entries should be sequential. If you look at the data set, it displays completely erratic behavior for all chunks, due in part to my oversite with regard to disabling interrupts before reading or manipulating my counter or the array itself.

Thanks, again, Sir Badley.

Serial.print/write etc are not instant and they are blocking.

In other words if serials output buffer is full then your program hangs until there is enough space to complete the write. But of course the isr keeps on modifying the data and no matter what baud rate you use serial is very slow compared with a 16MHz processor.

Mark

Serial.print/write etc are not instant and they are blocking

Only if the output buffer is full.

And next I said

In other words if serials output buffer is full then your program hangs until there is enough space to complete the write

Mark

THEtheChad:
Thanks, again, Sir Badley.

You are quite welcome.

Nick Gammon has written a very good description of interrupt handling available from his website...

Just wrote this snippet of code and wanted to bounce it off you guys. It works under the assumption that reading a byte (uint8_t) is done instantly and can not be interrupted which Coding Badly alluded to.

#define MAX_POWER 255

//
// Pin definitions
//
#define ENCODER_A 2
#define ENCODER_B 3

#define MOTOR_CURRENT_1 A0
#define MOTOR_CURRENT_2 A1
#define MOTOR_VOLTAGE   A2

#define MOTOR_DIRECTION 10
#define MOTOR_PWM       11
#define MOTOR_FAULT     12
#define MOTOR_ENABLE    13

void setup(){
  Serial.begin(115200);

  // Pin setup
  pinMode(MOTOR_DIRECTION, OUTPUT);
  pinMode(MOTOR_PWM      , OUTPUT);
  pinMode(MOTOR_ENABLE   , OUTPUT);
  pinMode(MOTOR_FAULT    , INPUT );
  pinMode(ENCODER_A      , INPUT );
  pinMode(ENCODER_B      , INPUT );

  attachInterrupt(0, tick, RISING);
  
  digitalWrite(MOTOR_ENABLE, HIGH);
  analogWrite(MOTOR_PWM, MAX_POWER);
}

volatile unsigned long time = 0;
volatile uint8_t ticks = 0;

void tick(){
  ticks++;
  time = micros();
}

void loop(){
  uint8_t tick_count;
  unsigned long recorded;

  do{
    tick_count = ticks;
    recorded = time;
  }
  while(tick_count != ticks);

  Serial.println(recorded);
}

I'm grabbing the current number of ticks, immediately reading the timer value, then checking to see if the ticks I read match the current ticks that were recorded. If not, I know an interrupt occurred and that my data was corrupted, so I repeat the process. The reason I'm writing it this way is because I can not afford to disable the interrupts, as I want to keep extremely accurate tracks of how many encoder ticks I've received. Again, I'm assuming that a uint8_t can be read in a single pass and will remain uncorrupted by the interrupt.

THEtheChad:
Just wrote this snippet of code and wanted to bounce it off you guys. It works under the assumption that reading a byte (uint8_t) is done instantly and can not be interrupted which Coding Badly alluded to.

The long reason you cannot rely on it working...

https://www.kernel.org/doc/Documentation/volatile-considered-harmful.txt
http://www.open-std.org/jtc1/sc22/wg21/docs/papers/2006/n2016.html
Nine ways to break your systems code using volatile – Embedded in Academia ...#5; references the AVR processor

The short reason... the compiler is free to reorder the assignments to tick_count and recorded in the do/while.

The reason I'm writing it this way is because I can not afford to disable the interrupts...

The timer 0 overflow handler disables interrupts. You haven't mentioned it being a problem.

...as I want to keep extremely accurate tracks of how many encoder ticks I've received.

What's the correlation between disabling interrupts for five clock cycles (313 nanoseconds) and missing an encoder tick? Is the size of your encoder measured in Ångströms?

THEtheChad:
The reason I'm writing it this way is because I can not afford to disable the interrupts, as I want to keep extremely accurate tracks of how many encoder ticks I've received. Again, I'm assuming that a uint8_t can be read in a single pass and will remain uncorrupted by the interrupt.

However an interrupt is "remembered" if interrupts are disabled, so you won't miss it unless you wait too long. And as Coding Badly said, the time it spends servicing a timer interrupt means it won't be totally accurate anyway (the timer amount anyway).

If you want "tick_count" and "recorded" to match the same event, you have to disable interrupts while obtaining those two variables. The access to them is not atomic.

In particular, "recorded" may be corrupted as well as out of sync with tick_count.

Imagine for a moment that the processor is copying "time" into "recorded" and after copying two of those four bytes, an interrupt occurs, and also imagine that a byte has overflowed.

So for example:

Old value: 0x0000FFFF
New value: 0x00010000

Depending on the order in which bytes are copied (and it's an 8-bit machine after all) the copy might end up being:

0x0001FFFF

Or even:

0x00000000

This sort of stuff is covered in my page about interrupts, and in particular "critical sections":

However an interrupt is "remembered" if interrupts are disabled, so you won't miss it unless you wait too long.

One of them (of each type) is. They are not queued, though. Diddle too long and you WILL miss interrupts.

It sounds to me like you have a problem with the hardware. Have you thought about asking the designers to fix/redesign it?