micros() bug?

linuxgeek

Well-known member
I am using an interrupt with a timer, and measure the micros() for the interrupt.

I recently started getting odd values for micros. For instance here's some output:

Code:
volatile unsigned long time1;

/**                                                                                                    
 * For recording timing of interrupt function                                                          
 */
void captureSamplesTimed() {
  time1=micros();
  captureSamples();
  time1= micros() - time1;
  Serial.print("t: ");
  Serial.println(time1);
  Serial.flush();
}

Code:
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 4294966297
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 1
t: 2
t: 1
t: 1

I realize that this is like it's rolling over, cause the value is about at the maximum value of an unsigned int.

I was using a micros() call in the loop, so I took out all other references to micros().

I now separated it out as time1, time2, and time.

I also removed from the interrupt that it does anything except measuring micros().

I'll start a new sketch that just does the timing, but I haven't done that yet.

Oddly with this code:
Code:
/**                                                                                                    
 * For recording timing of interrupt function                                                          
 */
void captureSamplesTimed() {
  time1=micros();
  //captureSamples();                                                                                  
  time2=micros();
  time=time2-time1;
  if(time>10) {
    Serial.print("t1: ");
    Serial.println(time1);
    Serial.print("t2: ");
    Serial.println(time2);
    Serial.print("t: ");
    Serial.println(time);
    Serial.flush();
  }
}

I get this:
Code:
t1: 8026999
t2: 8026000
t: 4294966297
t1: 8087999
t2: 8087000
t: 4294966297
t1: 8148999
t2: 8148000
t: 4294966297
t1: 8209999
t2: 8209000
t: 4294966297
t1: 8270999
t2: 8270000
t: 4294966297
t1: 8331999
t2: 8331000
t: 4294966297
t1: 8392999
t2: 8392000
t: 4294966297
t1: 8453999
t2: 8453000
t: 4294966297
t1: 8514999
t2: 8514000
t: 4294966297
t1: 8575999
t2: 8575000
t: 4294966297
t1: 8636999
t2: 8636000
t: 4294966297
t1: 8697999
t2: 8697000
t: 4294966297
t1: 8758999
t2: 8758000
t: 4294966297

But if I take out the test for >10, I get this:
Code:
t1: 8032798
t2: 8032799
t: 1
t1: 8033042
t2: 8033043
t: 1
t1: 8033286
t2: 8033287
t: 1
t1: 8033530
t2: 8033531
t: 1
t1: 8033774
t2: 8033775
t: 1
t1: 8034018
t2: 8034019
t: 1
t1: 8034262
t2: 8034263
t: 1
t1: 8034506
t2: 8034507
t: 1
t1: 8034750
t2: 8034751
t: 1
t1: 8034994
t2: 8034995
t: 1
t1: 8035238
t2: 8035239
t: 1

the interrupt is at 4096Hz.

When I do the test if it's >10, I don't know why t2 is SMALLER than t1.
 
Will do, when I can get back to it later on. I'll see if I can trim it down first and still get the same error so you don't have to wade thru my cruft.
Otherwise I'll send it all or at least something that has the issue. Thanks.
 
Ok, it's really hard to predictably get this to occur.
The exact same sketch will sometimes never do it, upload it again and sometimes it'll do it every single interrupt. Sometimes it'll take awhile but will happen. Sometimes, it seems that if it happens once, the next upload will have it immediately. But that doesn't seem to be the case every time either.

I paired down the code a bit, and increased the interrupt rate to try and make it more likely.
I'm going to bet it won't have an error for you.
Oddly, the time2 always seems to be 999 microseconds before time1. This is with different interrupt rates, etc.

Sorry I couldn't pair it down more, but I was afraid I would not get the error any longer.
Attached. I wanted to make sure you had everything, so I'm attaching related files.
 

Attachments

  • pjrc_micros.zip
    143.1 KB · Views: 336
Oddly, the time2 always seems to be 999 microseconds before time1. This is with different interrupt rates, etc.

I take that back it's typically 99x, but not always 999. I just ran it and it was 996.
t1: 8080998
t2: 8080002
t: 4294966300
 
Thanks!

I'm running the program now and it is reproducing the bug here.

Will post as I learn more about what's causing this.....
 
I'm working on a fix now. The problem happens when calling micros() within an interrupt that has blocked the systick interrupt. So micros() is capturing the previous millis() count and adding the elapsed microseconds. I'm going to try detecting this case and adding 1000 to fix it. How exaclty, well, I'm still working on that........
 
Here's the fix.

In hardware/teensy/cores/teensy3/pins_teensy.c, replace this line

Code:
    if ((istatus & SCB_ICSR_PENDSTSET) && current > ((F_CPU / 1000) - 50)) count++;

with this:

Code:
    if ((istatus & SCB_ICSR_PENDSTSET) && current > 50) count++;
 
It is quite the puzzle trying to get the ticks counted accurately without losing any or creating non monotonicity. Is it the case with the current code that if anyone holds off interrupts for over one mS a count will be missed?
 
Yes. If you disable interrupts for period containing 2 systick timer rollovers, then yes, the millis count will fail to be updated. In the worst case, where the disable interrupts the instant before the systick interrupt, just slightly over 1ms will cause the millis() to lose 1ms of time.

With this patch, micro() will still read correctly for 1ms minus 50 cycles after the missed interrupt.... right up until the point where you must allow interrupts again for the millis count to remain accurate. I had originally intended micros to work this way, but I simply got the arithmetic wrong.

Actually, I had originally intended to set the systick timer for a very long period, perhaps 100 ms, or maybe just allow the full 24 bit rollover (which is a period of 174.76266 ms at 96 MHz) and then write a relatively complex interrupt routine and millis() and micro() to read the not-so-nice accumulated and partial count. I abandoned that effort, partially because the code got very complex, partially because it adds considerable overhead in the very commonly used millis() function, but mostly because I simply ran out of time of non-essential coding with the pressure of the kickstarter launch and shipping deadlines.
 
Here's the fix.

In hardware/teensy/cores/teensy3/pins_teensy.c, replace this line

Code:
    if ((istatus & SCB_ICSR_PENDSTSET) && current > ((F_CPU / 1000) - 50)) count++;

with this:

Code:
    if ((istatus & SCB_ICSR_PENDSTSET) && current > 50) count++;

So far, so good.
 
Hello,

I am using Teensy 2++ and comparing 2 micros() is also giving some strange results.

Do this bug also affects the Teensy 2++ micros() function?
 
This issue was fixed years ago. It is not known to exist on any Teensy model, even Teensy++ 2.0.

Of course, if you disable interrupts for more than 1 ms, both millis and micros will lose time.

Generally the way things work here is we expect you to post a complete (and hopefully concise) program which reproduces the problem. If your code is very large or has proprietary or secret info, trim it to a minimal program you can share just to demonstrate this issue.
 
Back
Top