MicroPython
ESP32 machine.lightsleep() frequently changes the ESP32 RTC backward by several seconds #19700
Replies: 8 comments 10 replies
|
Perhaps, you need to use |
|
Unfortunately, this won't help because the issue is that the ESP32 RTC value is being changed. If you were able to run the code provided for an hour (or so) I'd appreciate it – you may be able to reproduce the problem. |
|
To return to the original problem, I suggest printing the raw [EDIT] I haven't managed to replicate the negative offset. The RTC continues to keep correct time. The docs explain why lightsleep time can be short, but the long periods are a puzzler especially 9.612s. |
|
I have now run it for three hours without replicating the negative offset. Using my watch the RTC has remained accurate over that period (margin of error +- a very few seconds). For completeness code follows. Board is an original ESP-WROOM-32. import time, machine
duration_ms = 600 * 1000 # 10 minutes
while True:
time.sleep_ms(duration_ms - 1000)
datetime = machine.RTC().datetime()
dt1=datetime
before_time_ms = time.mktime((datetime[:3] + datetime[4:7] + (0, 0))) * 1000 + (datetime[7] // 1000)
machine.lightsleep(1000)
datetime = machine.RTC().datetime()
after_time_ms = time.mktime((datetime[:3] + datetime[4:7] + (0, 0))) * 1000 + (datetime[7] // 1000)
time_diff_ms = (after_time_ms - before_time_ms)
print(dt1, datetime)
if time_diff_ms <= 0:
print("RTC went backward by {0} ms".format(time_diff_ms))
elif abs(time_diff_ms - 1000) >= 100:
print("Slept for {0} ms".format(time_diff_ms)) |
|
Since we are measuring period for We can not use time.ticks_* for In fact I got the best result using time.ticks_* in my test runs. Consider these 3 # now#1
def now():
dt = machine.RTC().datetime()
return time.mktime((dt[:3] + dt[4:7] + (0, 0))) * 1000 + (dt[7] // 1000)# now#2
def now():
return time.ticks_ms() # in ms# now#3
def now():
return time.time_ns() // 1_000_000 # Convert ns to msThe test script: # test.py
import machine, time
# delay = 600 * 1000 # 10 minutes
delay = 10 * 1000 # 10 seconds
ms_sleep = delay - 1000
ls_ms = 1000
def now():
return time.ticks_ms() # use now#2
while True:
time.sleep_ms(ms_sleep)
t0 = now()
machine.lightsleep(ls_ms)
t1 = now()
print('Diff (ms):', time.ticks_diff(t1,t0), 'delta:', time.ticks_diff(t1,t0)-ls_ms)
# print('Diff (ms):', t1-t0, 'delta:', t1-t0-ls_ms)
# if we use now#1 or now#2We can get better results for now#1 and now#2 if we control gc manually with gc.disable() and gc.collect() The logic will be the same for 9+ minutes delay or 9+ seconds. |
I'm not measuring the The problem is: the ESP32 RTC is – apparently – changed by |
|
I don't understand - You mean import machine, time
delay = 1 * 1000 # 1 seconds
ms_sleep = delay - 50
ls_ms = 50
def now():
return time.ticks_ms() # in ms
while True:
time.sleep_ms(ms_sleep)
t0 = now()
machine.lightsleep(ls_ms) # light sleep 50 ms
t1 = now()
print('Diff (ms):', time.ticks_diff(t1,t0), 'delta:', time.ticks_diff(t1,t0)-ls_ms)The result I got: Here we did I'm running - MicroPython v1.30.0-preview.17.g47e9329e51 |
|
Maybe you have "bad" power supply. Waking up from lightsleep is power sensitive. |
|
OK, now I understand the problem a bit better. ESP32 uses two clock; 1) a high-speed crystal (40 MHz) and 2) a low-power RTC slow clock (150 kHz RC). The The clock#2 with internal RC oscillator drifts with temperature, voltage, and calibration errors. During lightsleep the low-power RTC slow clock counts the sleep ticks. When the ESP32 wakes up, the ESP-IDF sleep manager uses that RTC count to advance the hardware timer that drives time.ticks_ms(). The next |
|
I don't think RC oscillator drift can explain the errors @jamesquilty is reporting. Espressif don't specify a stability rating, but most RC oscillators trim to within a few % across the full temperature range. The biggest error James reported is -10 seconds in 1000ms. If that was forward drift it would be 10x (i.e. the nominal 150kHz RC oscillator would be running at 1.5MHz!), but recurring negative drift here implies that the clock is running so fast that it's frequently overflowing or something. It is likely that there's a bug somewhere when applying clock accounting between the RC oscillator and the internal clock, but I think it's a bug not a physical property. As per my comment below I'm curious if the problem goes away on newer MicroPython, as this part is handled by ESP-IDF. |
The ESP32 RTC momentarily losing power on light-sleep would certainly be one potential cause. The device has a dual-power system: it's receiving 11.9 V from mains power and the ESP32 is presently also powered by USB from a Raspberry Pi 4B. I don't think this is an external power issue, it might be an internal power-switching issue. |
@jamesquilty are you able to try your reproducer under MicroPython 1.29.0, please? Probably everyone else in this thread is running that version or a newer pre-release. Is there any other code running on the ESP32 board (i.e. a |
|
Thanks for everyone's attention on this problem, it's appreciated! Looking at the results, I think there's some evidence that the variability in the ESP32 RTC is random with a non-uniform probability distribution. The larger variations (-11 s observed by me, +9 s observed by @peterhinch) are rare while small variations of < ±1 s are common. As suggested by @projectgus, I updated to MicroPython 1.29.0 and, changing nothing else, ran the full code overnight with its current 25-minute period. I observed several examples of the RTC running backward during light sleep, as well as RTC elapsed times shorter and longer than the 1000 ms light sleep period. The appended selected results may be of interest, they are all consistent with 1000 ms passing in real time with the RTC gaining or losing time compared to the elapsed real time. Next Steps: I'll try testing this RTC⇆light-sleep issue on a USB-powered ESP32-WROVER-E-DevKitC (new). I'll also try the reproducer code with a longer time.sleep() period [10 mins was giving variations around 500 ± 200 ms on MicroPython 1.29.0]. I'll also try the reproducer code on the device with the full code's boot.py and main.py renamed. I'll also look into whether the raw ESP32 RTC register values can be read and stored as a diagnostic step. All this is likely to take me more than a few days to work through. Selected ResultsRTC indicates -1340 ms elapsed time; shows -2.5 ± 0.5 s offset from NITZ time. RTC indicates +2600 ms elapsed time; shows +2.0 ± 0.5 s offset from NITZ time. RTC indicates +790 ms elapsed time; shows -1.5 ± 0.5 s offset from NITZ. RTC indicates -1030 ms elapsed time; shows -2.4 ± 0.5 s offset from NITZ time. |
|
Thanks for the update, @jamesquilty.
FWIW this is probably a reasonable amount of variation for RTC RC timekeeping (0.8%). To do better than this you'll need a 32kHz crystal. Curious to see if the results change when you disable main.py and boot.py (and in particular don't configure any Wi-Fi on boot). |
Just to disambiguate: for |
|
I've tried some simple tests (I had limited time to spare) with the 25 minute sleep period and found:
That's expected behaviour. I manually interrupted I was in the REPL for the period 10:20:30 - 10:23:56 but I don't believe that's related to the anomalous RTC variation. |
|
FWIW, I was seeing some very high RTC drifts after switching to |
|
For completeness, output from Peter's code on several systems with v1.29.0: ESP32ESP32 DevKitC - Generic ESP32 module with SPIRAM ESP32-C6(Couldn't run: USB disconnected during sleep. I will file an issue if someone else hasn't) ESP8266The ESP8266 has a dismally inaccurate RTC. It was set at 12:09, and by 13:35 it thought it was only 13:22. RP2040Raspberry Pi Pico W STM32PyBoard v1.1 Yes, the first char of every second line is missing from pyboard output. |
Uh oh!
There was an error while loading. Please reload this page.
Uh oh!
There was an error while loading. Please reload this page.
I'm looking at scheduling a task and I've encountered some rather odd behaviour with
machine.lightsleep()running under MicroPython 1.26.1 on an ESP32-WROVER-B. I'm not entirely sure what's going on and before raising a bug report I wanted to ask in the discussions. The code:duration) in milliseconds,time.sleep_ms(duration -1000)[if the argument is negative thentime.sleep_msreturns immediately]machine.lightsleep(1000)for the final second, to ensure thatmachine.wake_reason()is set/reset.It's the last step that's problematic, what I see from logging
machine.RTC().datetime()with fractional seconds is thattime.sleep_ms()is accurate butmachine.lightsleep(1000)will either: (i) sleep for 1000 ms, (ii) apparently sleep for a few 10s to a few 1000s of ms or (iii) sleep for a negative amount of time which in the worst cases has been < -10000 ms. The most problematic is (iii) and I'm confident that this represents an actual change to the ESP32 RTC because subsequent code synchronises the ESP32 with NITZ and, in these cases, reverses the offset caused bymachine.lightsleep(). Three examples of backward steps (two large, one small):I was watching the large steps on the console and the real-time sleep period was ~1000 ms.
Making the reasonable assumption that if this was a known behaviour in the ESP32 or ESP32-WROVER-B then it would be mentioned somewhere in the documentation, I'm left wondering whether it's (a) an issue with the board or (b) an issue with MicroPython 1.26.1?
(a) I don't have an external oscillator connected to the
32K_XP/32K_XNpins, these pins are connected to a RGB LED (100 Ω current-limiting resistor in series; low to switch LED on), used as GPIO 32 and 33 and configured on boot withmachine.Pin(led_pin, machine.Pin.OUT, value=1). Transients on these pins might cause problems... but it's hard to understand how transients could wind the RTC backward by 5-10 seconds in 1 s real-time.(b) Maybe there's a bug in the MicroPython ESP32 port in the construction of
machine.lightsleep()?I've searched for Issues and while there have been some reports of
machine.lightsleep()anomalies, there's nothing like this. Does anyone else see this?Some code which reproduces the problem:
On first run on the REPL with 10 minute
durationI received "RTC went backward by -226 ms".Note: there appears to be an interaction with the
time.sleep_ms(duration_ms-1000): with shorter duration the RTC deviation is much less. For 10,000 ms the deviation was 1-4 ms for 120,000 ms the deviation increased to 25-100 ms and with 600,000 ms the RTC went backward.Edited to add: I see that light-sleep interrupts the printing of output to the console (connected by USB) and the actual code is both printing to the console and writing the log line to a file on a mounted microSD card. Again, it's hard to understand how this could wind the ESP32 RTC backward but... maybe?
All reactions