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

[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.

[Kees-van-der-Oord]

A slightly modified version of your test:

void test_micros2() {
  Serial.println("testing micros2 - send input to stop");
  while(!Serial.available()) {
    uint32_t t1 = micros();
    uint32_t t2 = micros();
    uint32_t period = t2 - t1;
    if(period > 4) {
      Serial.println(period);
    }
  }
  while(!Serial.available()) Serial.read();
  Serial.println("testing micros2 - finished");
}

shows that the time for the micros() call is 7 us when Serial is sending the first string, and then stays consistently at <= 4 us:

13:49:57.672 -> testing micros2 - send input to stop
13:49:57.672 -> 7
13:49:57.672 -> 7
13:49:57.672 -> 6
13:50:44.234 -> testing micros2 - finished

Note that I set the baud rate to 2000000 bps (I'm not sure the speed is applicable at all ...)

[greiman]

I have noticed that Serial is really high overhead. The Serial transmit interrupt causes pauses in SPI send.

What happens if you put a delay after each print?

[Kees-van-der-Oord]

I get unexpected variations in the output of the tests.
To get rid of the first slow timings, I added a delay or a call to Serial.flush().
But any change before or in the loop makes that the reported times for the call to micros() gets longer ???
E.G. uncommenting any line in this code will show this effect:

void test_micros2() {
  Serial.println("testing micros2 - send input to stop");
  //Serial.flush();
  //delay(2);
  while(!Serial.available()) {
    uint32_t t1 = micros();
    uint32_t t2 = micros();
    uint32_t period = t2 - t1;
    if(period > 4) {
      Serial.println(period);
      //Serial.flush();
      //delay(2);
    }
  }
  while(Serial.available()) Serial.read();
  Serial.println("testing micros2 - finished");
}

I guess this is due to compiler optimization side effects - leave that for now.

[Kees-van-der-Oord]

There is one difference with the R3: I use GPT 0 timer to do some tasks, and the interrupt priority of the GPT timer seems to be higher than the AGT timer used for the millis() implementation. In stress, the agt_time_ms variable doesn't get updated anymore :-). Any suggestions to promote the AGT interrupt ?

[manitou48]

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

this looks like it' s requesting AGT 1 -- should it be requesting AGT 0?

[Kees-van-der-Oord]

thanks: I corrected it.

[manitou48]

OK i modified time.cpp with your updates. micros() seems to be working. Good job.

[Kees-van-der-Oord]

Good to hear the good news.
I tested several scenarios:

1. specify the timer configurations as constants: micros() takes 3.6 us
   these constants are platform depending ...

2. specify the timer configurations as variables, like the current implementation: 3.8 us
   this is a more platform independent solution.

I guess we should go for the extra 3% speed and not for the nice solution ....

[Kees-van-der-Oord]

I tried to push the changes to a new branch in 'https://github.com/arduino/ArduinoCore-renesas/', but it says:

Failed to push to the remote repository. See the Output window for more details.
Pushing fix-for-micros
Remote: Permission to arduino/ArduinoCore-renesas.git denied to Kees-van-der-Oord.
Error encountered while pushing to the remote repository: Git failed with a fatal error.
Git failed with a fatal error.
unable to access 'https://github.com/arduino/ArduinoCore-renesas/': The requested URL returned error: 403

What is the correct way to submit this solution ?
time.zip

[greiman]

What is the correct way to submit this solution ?

I was hoping someone else would answer. In the past things I worked on were submitted by a person with Arduino contacts.

[per1234]

What is the correct way to submit this solution ?

Hi @Kees-van-der-Oord and @greiman. Thanks for your interest in contributing! Proposals for changes to the codebase hosted in this repository should be submitted via "pull requests" (PRs).

An overview of the contribution workflow:

1. Fork the repository.
2. Clone your forked repository.
3. Create a branch
4. Make the changes you want to propose in your local clone of the repository.
5. Commit the changes.
6. Push the branch to your fork on GitHub.
7. Submit the pull request from your fork to the parent repository.

---

ⓘ It is also possible to edit files and make commits via the GitHub interface, eliminating the need to make a local clone. But contributors often find that it is more convenient to work with the files on their own computer for any significant development work and I see you are already working with a local clone.

---

There is a detailed guide to contributing via the pull request system here:

https://docs.github.com/pull-requests/collaborating-with-pull-requests/proposing-changes-to-your-work-with-pull-requests/about-pull-requests

[Kees-van-der-Oord]

I submitted my first pull request: !

[aentinger]

Fixed by merging #52 .