strange micros() behavior

[rayozzie]

Hardware:

Board: Adafruit Huzzah32 Feather
Core Installation/update date: 19-Feb-2018
IDE name: Arduino 1.8.5
Flash Frequency: 80Mhz
Upload Speed: 921600

Description:

I am trying to use a run-of-the-mill Arduino e-paper display library that happens to watch a certain "busy" pin, and reports debug info via Serial.printf() when the pin appears busy for too long. The code is a delay(1) spin loop, and it is almost instantly reporting timeout.

This caused me to write some of my own debug code to test the behavior of the micros() implementation in the HAL.

Here is the code test code:
void test() {
unsigned long startUs = micros();
unsigned long startMs = millis();
while (millis() < startMs + 10000)
delay(1);
unsigned long nowUs = micros();
unsigned long nowMs = millis();
Serial.printf("milliseconds elapsed: %ld\n", nowMs - startMs);
Serial.printf("microseconds elapsed: %ld\n", nowUs - startUs);
}

When I call this test() function near program initialization, this is what I get:
milliseconds elapsed: 10000
microseconds elapsed: 9999563

...which is correct, of course. But later, at the moment I get one of these timeouts, I add a call to this test method, which then returns the following amazingly strange result:

milliseconds elapsed: 10000
microseconds elapsed: 27895357

The value of microseconds elapsed in that period of time is quite repeatable - i.e. in various calls it will get values such as 27895064, 27895697, 27895548, and so on.

Again, if I just do the call to the test function in other parts of the code - even after this strange result has happened - it returns the correct value of ~10k mS elapsed and ~10M uS elapsed.

This is just a simple display driver that is using SPI, and there are no ISRs involved. It's just sending commands to the SPI device and is waiting in the delay(1) spin loop until they return.

I'm looking for some feedback here as to what might potentially be happening to make the microsecond clock appear to be counting at 2.7x faster than it should be, but only for brief instants. So strange.

Thanks in advance for any ideas you might have.

[stickbreaker]

@rayozzie do you have a separate task that is also calling micros()?

if so, check out issue #1160. and pr #1165

Chuck.

[ghost]

To be reliable, micros() needs to be called multiple times over a 17 second period for the overflow code to work. That's the ccount (cycle count) special register's limit for overflows. 17.895697 seconds to be more precise. Add in 10 seconds and I got close to your numbers. millis() doesn't use micros() to work - and delay() doesn't either. Try putting a micros() call within the delay(1) while loop and see what happens.

[ghost]

(That's if you're not using a 2nd task as Chuck suggests)
Also, I would write the while loop like this to deal with overflow conditions:
while (millis() - startMs < 10000)

[rayozzie]

Sigh. This is quite disappointing HAL behavior for a function that is going to impact arbitrary code. My code is not multitasking and I do not use micros() myself, although I don’t know what libraries may use it – and so I can’t know for certain whether or not it is being called by multiple tasks. FYI, I did as you suggested – adding a single call to micros() within the loop just to see what happens. Check out the output. milliseconds elapsed: 10000 microseconds elapsed: 475287312 milliseconds elapsed: 10000 microseconds elapsed: 1423759478 milliseconds elapsed: 10000 microseconds elapsed: -1403760776 milliseconds elapsed: 10000 microseconds elapsed: -1421657404 milliseconds elapsed: 10000 microseconds elapsed: -1421656960 Again, the code: unsigned long startUs = micros(); unsigned long startMs = millis(); while (millis() < startMs + 10000) { volatile unsigned long foo = micros(); delay(1); } unsigned long nowUs = micros(); unsigned long nowMs = millis(); Serial.printf("milliseconds elapsed: %ld\n", nowMs - startMs); Serial.printf("microseconds elapsed: %ld\n", nowUs - startUs); From: jasoroony <[email protected]> Reply-To: espressif/arduino-esp32 <[email protected]> Date: Saturday, March 3, 2018 at 5:03 PM To: espressif/arduino-esp32 <[email protected]> Cc: Ray Ozzie <[email protected]>, Mention <[email protected]> Subject: Re: [espressif/arduino-esp32] strange micros() behavior (#1168) To be reliable, micros() needs to be called multiple times over a 17 second period for the overflow code to work. That's the ccount (cycle count) special register's limit for overflows. 17.895697 seconds to be more precise. Add in 10 seconds and I got close to your numbers. millis() doesn't use micros() to work - and delay() doesn't either. Try putting a micros() call within the delay(1) while loop and see what happens. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub<#1168 (comment)>, or mute the thread<https://github.com/notifications/unsubscribe-auth/AAuhPf0Lqt7QRGIl8JjoywKaDxu1-bDCks5taxM1gaJpZM4SbEty>.

[rayozzie]

Update: I manually applied this PR, and it fixes the problem completely. #1165 I hope this gets into the mainline code stream before long. Thank you all for your assistance; you’re tremendously responsive and helpful individuals. From: chuck todd <[email protected]> Reply-To: espressif/arduino-esp32 <[email protected]> Date: Saturday, March 3, 2018 at 4:22 PM To: espressif/arduino-esp32 <[email protected]> Cc: Ray Ozzie <[email protected]>, Mention <[email protected]> Subject: Re: [espressif/arduino-esp32] strange micros() behavior (#1168) #1165<#1165>

[stickbreaker]

@rayozzie this patch has been applied to the main repo, you should be able to close this issue.

Chuck.

[rayozzie]

Fantastic. Thanks.

[emilfihlman]

Could it be that this has been accidentally undone or the fix was not sufficient?

I'm getting micros behaviour that jumps massively around on latest.

[alcio85]

same strange behavior in my case.
i'm inside a isr to calculate rpm from a motor encoder,
the issue is with micros() but also "esp_timer_get_time" wont fix the issue...
if i remove micros() the pulse count are correct and consistent, if i use micros() randomly in few seconds i got board restarts....

i'm compiling from arduino ide with 2.0.14 esp32 board library, using a esp32 dev kit 38pin

[anvgfr]

Hello,
still get the same behavior with 2.0.17 with micros(), some times it return fake value. I used it to measure signal period but get inaccurate value.