Using micros() -- not working?

I am having some issues using micros() on an uno. I am obviously not getting accurate microseconds.

Results to iterate through 1,000,000 increments and test (tried initially with a 1,000 iterations):

Timer test

1, 172, 176, 4 us
2, 1000732, 1000736, 4 us
3, 2001676, 2001680, 4 us
4, 3002620, 3002624, 4 us
5, 4003568, 4003572, 4 us
6, 5004512, 5004516, 4 us
7, 6005460, 6005464, 4 us
8, 7006408, 7006412, 4 us
9, 8007356, 8007360, 4 us
10, 9008304, 9008308, 4 us
int count=0;
int tick=0;
unsigned long usStart = 0;
unsigned long usStop = 0;
 
void setup() {
  // put your setup code here, to run once:
  Serial.begin(9600);
  while (!Serial);
  Serial.println("Timer test\n");
}

void loop() {
  // put your main code here, to run repeatedly:
  if (count < 10){
    ++count;
    usStart = micros();
    noInterrupts();
    for (long i=0; i<1000000; i++) {
      tick++;
    }
    interrupts();
    usStop = micros();
    Serial.print(count);
    Serial.print(", ");
    Serial.print(usStart);
    Serial.print(", ");
    Serial.print(usStop);
    Serial.print(", ");
    Serial.print(usStop-usStart);   
    Serial.println(" us");
  }
  delay(1000);
}

From https://www.arduino.cc/en/Reference/Micros

On 16 MHz Arduino boards (e.g. Duemilanove and Nano), this function has a resolution of four microseconds (i.e. the value returned is always a multiple of four).

I understand that... however, I am doing an increment and test 1,000,000 times between readings. I should be getting something in the 500 ms. range (62.5 ns / clock cycle).

    for (long i=0; i<1000000; i++) {
      tick++;
    }

You never use the i or tick variables. Are you sure that the whole for loop is not being optimized away by the compiler ?

UKHeliBob:
You never use the i or tick variables. Are you sure that the whole for loop is not being optimized away by the compiler ?

I had a version that I was printing the tick value as well-- same results.

Timer test

1, 16960, 172, 176, 4 us
2, -31616, 1001004, 1001008, 4 us
3, -14656, 2002236, 2002240, 4 us
4, 2304, 3003468, 3003472, 4 us
5, 19264, 4004644, 4004648, 4 us
6, -29312, 5005864, 5005868, 4 us
7, -12352, 6007100, 6007104, 4 us
8, 4608, 7008332, 7008336, 4 us
9, 21568, 8009508, 8009512, 4 us
10, -27008, 9010732, 9010736, 4 us
int count=0;
int tick=0;
unsigned long usStart = 0;
unsigned long usStop = 0;
 
void setup() {
  // put your setup code here, to run once:
  Serial.begin(9600);
  while (!Serial);
  Serial.println("Timer test\n");
}

void loop() {
  // put your main code here, to run repeatedly:
  if (count < 10){
    ++count;
    noInterrupts();
    usStart = micros();
    for (long i=0; i<1000000; i++) {
      tick++;
    }
    usStop = micros();
    interrupts();
    Serial.print(count);
    Serial.print(", ");
    Serial.print(tick);
    Serial.print(", ");
    Serial.print(usStart);
    Serial.print(", ");
    Serial.print(usStop);
    Serial.print(", ");
    Serial.print(usStop-usStart);   
    Serial.println(" us");
  }
  delay(1000);
}

You are loosing the micros() because you disable interrupts for the one million round loop.

Remove the crappy noInterrupts() and interrupts() calls and look at the real timing.

Timer test

1, 120, 377472, 377352 us
2, 1378424, 1755708, 377284 us
3, 2756928, 3134208, 377280 us
4, 4135428, 4512712, 377284 us
5, 5513936, 5891224, 377288 us
6, 6892444, 7269732, 377288 us
7, 8270956, 8648236, 377280 us
8, 9649456, 10026740, 377284 us
9, 11028016, 11405296, 377280 us
10, 12406628, 12783916, 377288 us

Whandall:
You are loosing the micros() because you disable interrupts for the one million round loop.

Remove the crappy noInterrupts() and interrupts() calls and look at the real timing.

I added the noInterrupts() to see if that would help. I did not have them initially…

removed them and same results:

Timer test

1, 16960, 172, 176, 4 us
2, -31616, 1001000, 1001004, 4 us
3, -14656, 2002232, 2002236, 4 us
4, 2304, 3003460, 3003460, 0 us
5, 19264, 4004632, 4004636, 4 us
6, -29312, 5005856, 5005860, 4 us
7, -12352, 6007092, 6007096, 4 us
8, 4608, 7008324, 7008328, 4 us
9, 21568, 8009504, 8009508, 4 us
10, -27008, 9010728, 9010732, 4 us
int count=0;
int tick=0;
unsigned long usStart = 0;
unsigned long usStop = 0;
 
void setup() {
  // put your setup code here, to run once:
  Serial.begin(9600);
  while (!Serial);
  Serial.println("Timer test\n");
}

void loop() {
  // put your main code here, to run repeatedly:
  if (count < 10){
    ++count;
    //noInterrupts();
    usStart = micros();
    for (long i=0; i<1000000; i++) {
      tick++;
    }
    usStop = micros();
    //interrupts();
    Serial.print(count);
    Serial.print(", ");
    Serial.print(tick);
    Serial.print(", ");
    Serial.print(usStart);
    Serial.print(", ");
    Serial.print(usStop);
    Serial.print(", ");
    Serial.print(usStop-usStart);   
    Serial.println(" us");
  }
  delay(1000);
}
for (long i=0; i<1000000; i++) {
      tick++;
    }

akatick += 1000000;?

Your code produces

Timer test

1, 16960, 104, 377472, 377368 us
2, -31616, 1378600, 1755880, 377280 us
3, -14656, 2757244, 3134532, 377288 us
4, 2304, 4135892, 4513180, 377288 us
5, 19264, 5514484, 5891768, 377284 us
6, -29312, 6893120, 7270408, 377288 us
7, -12352, 8271764, 8649052, 377288 us
8, 4608, 9650412, 10027692, 377280 us
9, 21568, 11029044, 11406328, 377284 us
10, -27008, 12407776, 12785064, 377288 us

Not on my Uno. I posted the results last.

But on my Nano, on 1.6.12 Win7 64b.

Very Very odd. I just tried it on two different 'brands' of unos and three boards. Same results. I am using a mac. I am going to try this on a Windows 10 box.

UPDATE:
I just tried this on Windows 10 machine and it worked as expected.

WHY IS THIS NOT WORKING ON A macOS MACHINE!?!

Maybe uploading on your Mac is broken/disfunctional?

The IDE versions may have different optimizer settings?

Hmm-- I am going to start a new topic asking the macOS question.

micros() works as expected when complied and uploaded from Windows 10 machine; however, my macOS complied and uploaded code does not work.

I am having issues with timing code using micros() so I wrote some test code to understand why. I am iterating through 1,000,000 increments which takes 377 ms (or 377 µs each). The macOS code only says 4 µs regardless of the number of iterations in the loop.

Windows 10 (EXPECTED) results:

Timer test

1, 16960, 104, 377472, 377368 us
2, -31616, 1378600, 1755880, 377280 us
3, -14656, 2757244, 3134532, 377288 us
4, 2304, 4135892, 4513180, 377288 us
5, 19264, 5514484, 5891768, 377284 us
6, -29312, 6893120, 7270408, 377288 us
7, -12352, 8271764, 8649052, 377288 us
8, 4608, 9650412, 10027692, 377280 us
9, 21568, 11029044, 11406328, 377284 us
10, -27008, 12407776, 12785064, 377288 us

macOS 10.12.3 results (unexpected):

Timer test

1, 16960, 172, 176, 4 us
2, -31616, 1001000, 1001004, 4 us
3, -14656, 2002232, 2002236, 4 us
4, 2304, 3003460, 3003460, 0 us
5, 19264, 4004632, 4004636, 4 us
6, -29312, 5005856, 5005860, 4 us
7, -12352, 6007092, 6007096, 4 us
8, 4608, 7008324, 7008328, 4 us
9, 21568, 8009504, 8009508, 4 us
10, -27008, 9010728, 9010732, 4 us

Code:

int count=0;
int tick=0;
unsigned long usStart = 0;
unsigned long usStop = 0;
 
void setup() {
  // put your setup code here, to run once:
  Serial.begin(9600);
  while (!Serial);
  Serial.println("Timer test\n");
}

void loop() {
  // put your main code here, to run repeatedly:
  if (count < 10){
    ++count;
    //noInterrupts();
    usStart = micros();
    for (long i=0; i<1000000; i++) {
      tick++;
    }
    usStop = micros();
    //interrupts();
    Serial.print(count);
    Serial.print(", ");
    Serial.print(tick);
    Serial.print(", ");
    Serial.print(usStart);
    Serial.print(", ");
    Serial.print(usStop);
    Serial.print(", ");
    Serial.print(usStop-usStart);   
    Serial.println(" us");
  }
  delay(1000);
}

UPDATE:

I updated the IDE to 1.8.1 on my macOS and this fixed the issue.

micros() works as expected when complied and uploaded from Windows 10 machine; however, my macOS complied and uploaded code does not work.

I would say "Optimization works as expected on the Mac, but on windows the obvious loop optimization isn't done", but figuring out why they're different will be worth some effort...

1,000,000 increments which takes 377 ms (or 377 µs each).

377ns each. Which is ... not quite believable. Incrementing an int (16bits) is at least two cycles, incrementing (or decrementing) the long loop counter should be at least 4 cycles. Each cycle is 62.5ns on a 16MHz AVR, so that 6 cycles uses up 375ns, and you haven't actually looped yet.

Needs further investigation...

This is a bit weird...
At -O1 it does the loop a million times, but updates ticks only after the loop. This gives the ~377 ms times.
At -O2 or -Os the loop is removed.

-O1

        call micros
	sts usStart,r22
        sts usStart+1,r23
        sts usStart+2,r24
        sts usStart+3,r25

        lds r18,tick
        lds r19,tick+1

        ldi r24,lo8(64)
        ldi r25,lo8(66)
        ldi r26,lo8(15)
        ldi r27,0
.L5:
        sbiw r24,1
        sbc r26,__zero_reg__
        sbc r27,__zero_reg__
        brne .L5

        movw r24,r18
        subi r24,-64
        sbci r25,-67
        sts tick+1,r25
        sts tick,r24

        call micros
        sts usStop,r22
        sts usStop+1,r23
        sts usStop+2,r24
        sts usStop+3,r25

-O2

        call micros
        sts usStart,r22
        sts usStart+1,r23
        sts usStart+2,r24
        sts usStart+3,r25

        lds r24,tick
        lds r25,tick+1
        subi r24,-64
        sbci r25,-67
        sts tick+1,r25
        sts tick,r24

        call micros
        sts usStop,r22
        sts usStop+1,r23
        sts usStop+2,r24
        sts usStop+3,r25

I found the same. But not with 1.8.1. 1.8.1 also starts using "-flto" (link time optimization) in addition to -Os.
Perhaps that doesn't work quite so well as it ought.