`micros()` sometimes returns incorrect value

[greiman]

Here is the problem - in this program bgn is often larger than end.

void setup() {
  Serial.begin(9600);
  while(!Serial) {}
  Serial.println("bgn, end, bgn - end");
  for (uint32_t i = 0; i < 10000; i++) {
    uint32_t bgn = micros();
    uint32_t end = micros();
    if (bgn > end) {
      Serial.print(bgn);
      Serial. print(',');
      Serial.print(end);
      Serial.print(',');
      Serial.println(bgn - end);
    }
  }
}
void loop() {
}

Here is the print out for the first few cases with bgn > end.

bgn, end, bgn - end
25992,25000,992
43992,43000,992
65993,65001,992
83994,83002,992

Wonder if the interrupt protection is correct. 1000 is a clue.

unsigned long micros() {
	// Convert time to us
	NVIC_DisableIRQ(main_timer.get_cfg()->cycle_end_irq);
 	uint32_t time_us = ((main_timer.get_period_raw() - main_timer.get_counter()) * 1000 / main_timer.get_period_raw()) +  (agt_time_ms * 1000); 
	NVIC_EnableIRQ(main_timer.get_cfg()->cycle_end_irq);
	return time_us;
}

[manitou48]

i think the begin() frequency is wrong for a 1 ms tick
main_timer.begin(TIMER_MODE_PERIODIC, AGT_TIMER, 0, 2000.0f, 0.5f, timer_micros_callback);

shouldn't it be 1000.0f

[manitou48]

for interrupts, maybe try noInterrupts() and interrupts(), or stronger rollover test?? I don't have an R4 to test yet

[greiman]

It has a high probability of being an interrupt problem with an occasional extra tick in agt_time_ms.
A call to micros() takes about 8μs. That's why the difference is 992μs.

I found it because of a problem with the bgn call. It also happens with the end call.

I changed the program:

void setup() {
  Serial.begin(9600);
  while(!Serial) {}
  Serial.println("bgn, end, end - bgn");
  for (uint32_t i = 0; i < 10000; i++) {
    uint32_t bgn = micros();
    uint32_t end = micros();
    if (bgn > end || (end > bgn && (end - bgn) > 900)) {
      Serial.print(bgn);
      Serial. print(',');
       Serial.print(end);
      Serial. print(',');
      Serial.println(int(end - bgn));
    }
  }
}
void loop() {
}

Then you see both cases:

bgn, end, end - bgn
23991,23000,-991
42001,43012,1011
60992,60001,-991
80991,80000,-991
99001,100012,1011
119002,120014,1012
140993,140001,-992
161001,162012,1011
182991,182000,-991
203000,204011,1011
227991,227000,-991
247000,248011,1011
268992,268000,-992
289001,290013,1012

[greiman]

@manitou48

for interrupts, maybe try noInterrupts() and interrupts(), or stronger rollover test?? I don't have an R4 to test yet

noInterrupts() and interrupts() is not an answer. In Uno R3 you can call micros() from an ISR. Here is the code for R3:

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());
}

[greiman]

One more wish. It would be nice if micros() was faster on R4. Here is a test on R4 and R3:

void setup() {
  Serial.begin(9600);
  while (!Serial) {}
  for (int i = 0; i < 10; i++) {
    uint32_t bgn = micros();
    uint32_t end = micros();
    Serial.println(end - bgn);
    delay(100);  // allow print to finish
  }
}
void loop() {}

R3 output:

4
4
4
4
4
4
4
4
4
4

R4 output:

8
9
8
8
9
9
8
9
9
8

R4 clock 48MHz, R3 16MHz. Clock three times faster micros() less than half as fast.

[Kees-van-der-Oord]

The issue happens in this scenario:

1. interrupts are disabled
2. the timer overflows (counter is reset from 0 to 3000) and the interrupt request bit is set
3. the counter is read out and used to calculate the time with agt_time_ms'
4. interrupts are enabled
5. the interrupt handler increments agt_time_ms

The Uno R3 code micros() reads the state of the interrupt request flag to handle this situation.
Is something similar possible for the R4 ?

[Kees-van-der-Oord]

Maybe the TUNDF bit of the AGTCR register ?

[Kees-van-der-Oord]

I would propose to configure the timer with a clock divider of 8 (24 MHz / 8 = 3000 ticks per ms):

main_timer.begin(TIMER_MODE_PERIODIC, AGT_TIMER, 0, 3000, 1, TIMER_SOURCE_DIV_8, timer_micros_callback);

The micros implementation will be simplified to:

unsigned long micros() {
  // return time in us
  NVIC_DisableIRQ(main_timer.get_cfg()->cycle_end_irq);
  uint32_t ms = agt_time_ms;
  uint32_t cnt = main_timer.get_counter();
  if (R_AGT0->AGTCR_b.TUNDF && (cnt > 1500)) ++ms; // underflow occurred just before reading the counter
  NVIC_EnableIRQ(main_timer.get_cfg()->cycle_end_irq);
  return  ms * 1000 + (2999 - cnt) / 3;
}

The test cnt > 1500 is necessary to check if the underflow happened before reading the counter.

This implementation passes all my tests ... Any other people that can confirm this works fine ?

[Kees-van-der-Oord]

the simple test for above implementation is:

void test_micros() {
  Serial.println("testing micros - send input to stop");
  uint32_t t1,t2;
  t2 = micros();
  while(!Serial.available())
  {
    t1 = micros();
    if(t1 < t2)
    {
      Serial.print(t2);Serial.print(" ");Serial.println(t1);
    }
    t2 = t1;
  }
  while(Serial.available()) Serial.read();
  Serial.println("testing micros - finished");
}

This should yield no output, except when agt_time_ms wraps after 1 hr and 10 minutes.

[greiman]

@Kees-van-der-Oord
What is the result of this test of performance?

void setup() {
  Serial.begin(9600);
  while (!Serial) {}
  for (int i = 0; i < 10; i++) {
    uint32_t bgn = micros();
    uint32_t end = micros();
    Serial.println(end - bgn);
    delay(100);  // allow print to finish
  }
}
void loop() {}

[Kees-van-der-Oord]

13:10:17.526 -> 4
13:10:17.655 -> 4
13:10:17.766 -> 4
13:10:17.846 -> 4
13:10:17.957 -> 4
13:10:18.067 -> 4
13:10:18.161 -> 4
13:10:18.287 -> 3
13:10:18.366 -> 3
13:10:18.491 -> 4

[greiman]

@Kees-van-der-Oord
Thanks. Nice fix and improved performance.

[Kees-van-der-Oord]

It takes 1 hour and 10 minutes before agt_time_ms wraps around ...
To test the wrap faster, I temporary changed the initialization from 0 to 10 sec before wrap.
The output shows:

13:15:21.697 -> hello world
13:15:24.060 -> testing micros - send input to stop
13:15:29.609 -> 4294967293 5

So it seems it handles the wrap scenario correctly as well ...

[greiman]

@Kees-van-der-Oord

Great test. I actually thought about that since I have users who run my libraries long enough for that to happen.