time.sleep() inaccuracies on Windows 7 (with a Metro M4 Express)

[CFRED86]

I was encouraged to post this issue here after discussing it on the Adafruit Metro M4 Express forums - here is the thread.

Essentially it seems like time.sleep() provides inaccurate intervals on Windows 7. Below are excerpts from the thread referenced above, but it's also worth noting that the release notes stated there were changes to the sleep functionality in CP 6.0.0 which may have introduced issues. I have also confirmed that sleep works properly (for my needs) in prior releases and this issue first appears in 6.x.

• works fine on my Windows 10 workstation (at my desk), but not on my Windows 7
• sleep of ~0.1 <= x < 1.0 seconds, then my output is a period of 1.0 second. If I use a period of 1.0 second, then my output immediately jumps to 2.0 seconds.
• If the sleep duration is very short (e.g. 0.01 or less), then the code execution appears to either stop/crash or grind to a near halt.

3.1.2 (with 3.x library) worked
4.1.0 (with 3.x library) worked - I could not find the 4.x library
5.0.0 (with 5.x library) worked
5.3.1 (with 5.x library) worked
6.0.0 (with 6.x library) does not work - appears to hang during time.sleep()

[dkirkby]

I can confirm that time.sleep hangs with 6.0.1 (on a Mac using Mu editor, in case that is relevant).

[DavePutz]

I was not able to reproduce the Win 7 issue using either Putty or Mu; time.sleeps of .5 seconds were accurate. I did see that when I tried very small sleep values (i.e. .01) that occasionally the time.monotonic() would jump by .06. I suspect this may be due to running some background task, but it was not a 'near halt' as you reported. Have you tried loading the latest Circuitpython Windows 7 drivers linked from https://learn.adafruit.com/welcome-to-circuitpython/troubleshooting?

[CFRED86]

Yes, I did have the latest drivers installed - the ones as of early November 2020. The Adafruit moderator confirmed that they looked good, as well. The drivers did fix other problems related to Windows 7 (e.g. being able to update the bootloader, etc.), but did not appear to affect my experience with the sleep issue. I tried both TeraTerm and Mu.

As you stated you were not able to reproduce the issue, and unfortunately I did not try this on another Win7 machine. Didn't look for one and don't know if there's another one readily available, but I can say the issue was very repeatable on the one I was using.

Could it be related to my use of an RTC (Adafruit DS3231)?

[dhalbert]

I can confirm that time.sleep hangs with 6.0.1 (on a Mac using Mu editor, in case that is relevant).

This is discussed in #3919 and appears to be a different problem, having to do with the REPL prompt printing on MacOS only and only on SAMD21 boards.

[dhalbert]

@CFRED86 Could you post a complete minimal program that exhibits the problem? Have you tried not actually reading from the sensor but just doing a time.sleep() loop? I will try to reproduce with your minimal program.

[CFRED86]

@dhalbert Yes, I can do that but not until sometime next week. In my own troubleshooting, I did two things. One, I functionally did what you described by removing all code which read the sensors and replaced them with with simple print() functions and an elapsed time calculation, though I still kept a majority of the program's structure and wrapped it in a 'while True' loop. I'll try to cut it down to a minimum and post it, but if I can't, I also did the following.

Two, I believe I also tried the following simple program, too: Adafruit - Interacting with the Serial Console. But I can't recall clearly, so I can try it again so I can confidently confirm yes or no.

[dhalbert]

I have reproduced this problem in 6.1.0-beta.3, and will be looking at a fix.

[CFRED86]

Ok - sounds good. I assume you don't need me to post a code example then?

[dhalbert]

Not right now; this is very odd, and I'm trying to narrow down the problem. I see time.sleep(0.1) taking way too long when done from the REPL. But if I ctrl-C a looping program and then do time.sleep(0.1), it's fine. I'll get back to you with a build to test to see if it solves your problem.

[DavePutz]

It looks like this behavior started after commit c7d87ce - "Fix autoreload on SAMD21" . Tracing showed that we are now sitting on the __WFI() call in port_idle_until_interrupt() until we get an interrupt once a second. As a result, sometimes a time.sleep of .1 will sleep nearly a second; other times it may return quickly, depending on how close to the 1/sec interrupt we were.

[dhalbert]

@DavePutz port_idle_until_interrupt() can be preceded by port_interrupt_after_ticks(), which is supposed to set up the RTC counter interrupt to interrupt after the actual requested sleep time, not just once a second.

I am at the moment debugging the SAMD21 M0 version of this, which has its own issues: _ticks_enabled, which is supposed to be a boolean, seems to be getting smashed from false to some random integer value. It sits between some USB buffers, so there may be an overflow somewhere. But if you can see some cause for not interrupting at the right time, that would be great to hear.

[dhalbert]

@DavePutz And another clue: _ticks_enabled exists on the SAMD51 version, but is not used except it's checked in port_interrupt_after_ticks(). If it gets smashed in the SAMD51 version too (as opposed to always staying false), that would explain what's going on, since it will disable setting up the interrupt to handle the specific time of the time.sleep().

circuitpython/ports/atmel-samd/supervisor/port.c

Lines 539 to 544 in a333597

	void port_interrupt_after_ticks(uint32_t ticks) {
	if (_ticks_enabled) {
	return;
	}
	_port_interrupt_after_ticks(ticks);
	}

So I will continue debugging this, concentrating on why _ticks_enabled is getting smashed; thanks for your observations which may confirm it.