Second call to micros() returns decreasing value when called around Mouse.move

I'm building an input lag tester for my computer using a SparkFun Pro Micro 3.3V with a phototransistor. The Pro Micro has the USB HID support so the Mouse library works.

I've noticed that when I call micros() around Move.move it sometimes gives me decreasing values instead of monotonically increasing values.

I found this thread from 2017 where someone seems to be encountering the same problem as me (i.e. non-monotonically-increasing return values from micros(), but the thread was derailed by people arguing about what "consecutive" means - I didn't see any solution posted).

Here is my minimum repro:

#include <Mouse.h>
#include <limits.h>

const int QRD1114_PIN = A1; // Sensor output voltage

unsigned long timeStart1 = 0;
unsigned long timeStart2 = 0;
unsigned long timeEnd    = 0;

const    byte INTERRUPT_PIN = 7;
volatile bool isMeasuring   = false;
volatile byte wasPressed    = false;
volatile int  pinIsrCount   = 0;

void pinIsr() {
  wasPressed = true;
  pinIsrCount++;
}

void setup()
{
  delay(1000);
  
  Serial.begin(9600);

  delay(1000);
  Serial.println("testing...");

  Mouse.begin(); //Init mouse emulation
  Serial.println("Mouse ready.");
  
  pinMode(INTERRUPT_PIN, INPUT_PULLUP);
  attachInterrupt(digitalPinToInterrupt(INTERRUPT_PIN), pinIsr, LOW); // when switch is open the pin is HIGH, when the switch is closed the pin is LOW.
}

unsigned long loopCount      = 0;
unsigned long loopCountStart = 0;
unsigned long loopCountEnd   = 0;

void loop() 
{
  loopCount++;
  
  if( wasPressed && !isMeasuring ) {
    Serial.println( "Now measuring." );
    
    isMeasuring = true;
    wasPressed = false;
    
    loopCountStart = loopCount;
    timeStart1 = micros();
    Mouse.move( SCHAR_MAX, 0 ); // `void move(signed char x, signed char y, signed char wheel = 0); `
    Mouse.move( SCHAR_MAX, 0 ); // `void move(signed char x, signed char y, signed char wheel = 0); `
    timeStart2 = micros();

    Serial.println( "loopCountStart:" );
    Serial.println( loopCountStart ); 
    Serial.println( "pinIsrCount:" );
    Serial.println( pinIsrCount ); 
    Serial.println( "timeStart1:" );
    Serial.println( timeStart1 );
    Serial.println( "timeStart2:" );
    Serial.println( timeStart2 );
    Serial.println( "diff:" );
    Serial.println( timeStart2 - timeStart1 );
  }
  else if( wasPressed && isMeasuring ) {
     isMeasuring = false;
     wasPressed = false;

     Serial.println( "Restarting." );
     Serial.println();
     Serial.println();
  }
}

When I run the program and short pin A1 (using a microswitch I have) I see this output in the Serial Monitor window.

I've annotated the times when it returned decreasing values with #here:

3:23:01.011 -> testing...
03:23:01.011 -> Mouse ready.
03:23:04.616 -> Now measuring.
03:23:04.616 -> loopCountStart:
03:23:04.616 -> 745004
03:23:04.616 -> timeStart1:
03:23:04.616 -> 5506840
03:23:04.616 -> timeStart2:
03:23:04.616 -> 5505568                            # here
03:23:04.616 -> diff:
03:23:04.616 -> 4294966024
03:23:04.616 -> Restarting.
03:23:04.616 -> 
03:23:04.616 -> 
03:23:06.691 -> Now measuring.
03:23:06.691 -> loopCountStart:
03:23:06.691 -> 1168562
03:23:06.691 -> timeStart1:
03:23:06.691 -> 7501216
03:23:06.738 -> timeStart2:
03:23:06.738 -> 7499944                            # here
03:23:06.738 -> diff:
03:23:06.738 -> 4294966024
03:23:06.738 -> Restarting.
03:23:06.738 -> 
03:23:06.738 -> 
03:23:10.624 -> Now measuring.
03:23:10.624 -> loopCountStart:
03:23:10.624 -> 1970816
03:23:10.624 -> timeStart1:
03:23:10.624 -> 11277592
03:23:10.624 -> timeStart2:
03:23:10.624 -> 11276320                        # here
03:23:10.624 -> diff:
03:23:10.624 -> 4294966024
03:23:10.624 -> Restarting.
03:23:10.624 -> 
03:23:10.624 -> 
03:23:11.959 -> Now measuring.
03:23:11.959 -> loopCountStart:
03:23:11.959 -> 2222478
03:23:11.959 -> timeStart1:
03:23:11.959 -> 12462552
03:23:11.959 -> timeStart2:
03:23:11.959 -> 12463328                       # this time it worked correctly
03:23:11.959 -> diff:
03:23:11.959 -> 776
03:23:11.959 -> Restarting.
03:23:11.959 -> 
03:23:11.959 -> 
03:23:14.791 -> Now measuring.
03:23:14.791 -> loopCountStart:
03:23:14.791 -> 2792180
03:23:14.791 -> timeStart1:
03:23:14.791 -> 15143280
03:23:14.791 -> timeStart2:
03:23:14.791 -> 15144056                     #  it worked correctly here too
03:23:14.791 -> diff:
03:23:14.791 -> 776
03:23:14.791 -> Restarting.
03:23:14.791 -> 
03:23:14.791 -> 
03:23:15.805 -> Now measuring.
03:23:15.805 -> loopCountStart:
03:23:15.805 -> 2984267
03:23:15.805 -> timeStart1:
03:23:15.805 -> 16048832
03:23:15.805 -> timeStart2:
03:23:15.852 -> 16049608                 #  and here too
03:23:15.852 -> diff:
03:23:15.852 -> 776
03:23:15.852 -> Restarting.
03:23:15.852 -> 
03:23:15.852 ->

"Mouse.move()" may tamper with interrupts, compiler may do optimizations. Try to define "timeStart*" as volatile.

It looks like the time is occasionally going backward by 2048 microseconds. The timer should go up by 776 microseconds but it sometimes goes down by 1272. When it happens it appears that bit 11 get's cleared when it shouldn't be but when the problem DOESN'T happen, sometimes bit 11 is left set.

My guess would be a compiler bug or a very subtle programming error.

Thanks johnwasser for finding the 2048, that made it a lot easier to find similar problems.
This is about the micros() with 2048, but I don't understand it :frowning: micros() goes backwards in time - #11 by jboyton - Programming Questions - Arduino Forum.
Is that a bug ? Should it be reported somewhere ?

Koepel:
This is about the micros() with 2048, but I don't understand it :frowning: micros() goes backwards in time - #11 by jboyton - Programming Questions - Arduino Forum. Is that a bug ? Should it be reported somewhere ?

That post from 2015 was talking about a third-party ATtiny core (not official Arduino). It sounds like they did not put in the part of the micros() code that checks for a timer overflow that has not yet caused an interrupt.
Timer0 overflows every 256*64 instruction cycles (1024 microseconds). I think you would have to have interrupts disabled for about 3 times that (3.072 milliseconds) to lose two overflow interrupts. Is the Mouse library doing something that could actually cause that?

@d

Danois90:
"Mouse.move()" may tamper with interrupts, compiler may do optimizations. Try to define "timeStart*" as volatile.

I did, it didn't make a difference. It also happens when I store micros() into a local variable, not a global.
Is there a way to reset state prior to calling micros()? I saw cli and sei but I saw those are called from within micros anyway.

johnwasser:
I think you would have to have interrupts disabled for about 3 times that (3.072 milliseconds) to lose two overflow interrupts.

On thinking deeper, failing to count one or more overflow interrupts can't make the time go back more than 1024 microseconds. The time will fall further and further behind real-time but it won't go back more than one overflow cycle.
I think the only way to have the time go back 2048 microseconds is to have the overflow counter go down by two. I have no idea how that could happen.

So.... what should I do?

Do I have a faulty unit? Can anyone else with a Pro Micro AVR reproduce the issue?

One thing to try: Change the interrupt mode from LOW to FALLING.

I also notice that the output doesn't match the code:

Code:

    Serial.println( "loopCountStart:" );
    Serial.println( loopCountStart );
    Serial.println( "pinIsrCount:" );
    Serial.println( pinIsrCount );
    Serial.println( "timeStart1:" );
    Serial.println( timeStart1 );

Output:

03:23:10.624 -> loopCountStart:
03:23:10.624 -> 1970816
03:23:10.624 -> timeStart1:
03:23:10.624 -> 11277592

Where did the output of pinIsrCount go?

This topic was automatically closed 120 days after the last reply. New replies are no longer allowed.