asyncio.sleep_ms(1) takes 10 msec to finish on esp32 #15594
|
Board : Esp-wroom-32 (tested on 2 boards) The following code should print a message every second but it takes about 10 seconds on the esp32. import asyncio
import time
async def test():
while True:
for i in range(1000):
await asyncio.sleep_ms(1)
print("Ok", time.time())
asyncio.run(test())How is this possible? |
Replies: 5 comments · 9 replies
|
I first thought "don't be ridiculous". Changed the code slightly to get rid of any floating point influence and to see the result more clearly: import asyncio
import time
async def test():
while True:
start = time.ticks_ms()
for i in range(1000):
await asyncio.sleep_ms(1)
print(time.ticks_diff(time.ticks_ms(), start), 'msecs')
asyncio.run(test())Ran it on linux: which is about what you would expect. Ran it on my ESP32 and ESP32-S3 and got: So certainly does appear ridiculous! Tried MP 1.23, 1.22, and 1.21 with same result. Sorry I can't explain this (without spending time going down a rabbit hole) but hopefully somebody else can. |
|
With a bit of testing it appears that any value for asyncio.sleep_ms < 10 is taken as 10. So, for example, with a range of 500 and a sleep_ms(2) a delay of 5000 ms occurs, similar results being obtained with other pairs of values in single figures that should deliver a 1 second delay. With a delay of 10ms / range 100 it works as expected. All tested on an ESP32 S3 running v1.24 preview. I'm sure someone will drill down into the code and tell us what's going on. |
|
If you can not use asyncio.sleep_ms for values below 10ms, this means that asyncio on a ESP32 is useless. Its amazing no one noticed this before. |
|
'Useless' is probably a bit strong. Asyncio.sleep_ms is absolutely fine for delays greater than 10ms and I can't remember ever needing a delay shorter than that. And I assume you meant asyncio.sleep_ms is useless not asyncio in general? I use asyncio on ESP32 frequently and it works just fine. It may be useless for a program that needs very short delays, but only then, and perhaps asyncio is inappropriate in that instance anyway. Probably no one has noticed because it's a rare requirement to need such short asynchronous delays. If you do need a short delay time.sleep_ms() works just fine. |
|
This is caused / limited by Espressif IDF default freertos tick rate. Any time the async loop sleeps it release the current thread in freertos so other background tasks can be handled. It turns out the default freertos tick rate is 100hz / 10ms so that's why it takes (at least) that long to get back to the the application thread. If your particular application actually needs more responsiveness than that it's generally safe to speed that tick rate up in a custom build to 1000hz / 1ms though I expect your power usage will go up too. |
|
Thank you Andrew! I learned something new today. Now after rebuilding a firmware with in sdkconfig.board I got the results I expected This may be useful information for others. |
|
For sure this would be a useful note in the documentation. Either in uasync or slerp_ms. |
I think there is a misunderstanding here. When you issue await asyncio.sleep_ms(1)on any microcontroller you will only get anything approaching a 1ms delay in the most trivial of applications. In practical code with multiple tasks the Please see the tutorial for further clarification. asyncio on ESP32 is far from useless. There are a number of substantial applications and libraries using it. |
|
To add to the above, the line await asyncio.sleep_ms(50)is best understood as "pause for a minimum of 50ms". The instruction await asyncio.sleep_ms(0)means "pause while every pending task gets some runtime". |
I know how asyncio works, I have written a lot of application using it. The point is that 1ms is not approximately 10ms. Esp8266 and RP-pico (which I have) behave as expected an take approximately 1ms if you choose asyncio.sleep_ms(1) and use a single task. The bad thing with the Esp32 is that if you use asyncio.sleep_ms(), al approximate delays appear in steps of 10mS. so asyncio.sleep_ms(20) is the same as asyncio.sleep_ms(29) and will last approximately 29 ms.
It can be less (tested on Esp32, esp8266 and RP-pico)
Luckily I found a solution to overcome the behaviour I described in this topic. It can be used if people need better resolution with the stock Micropython for the Esp32. See below. |
If this is the case it is a bug (in my opinion). I suggest you produce a repro and raise an issue. |
|
If I run the test program below on a raspberry pi pico (and take 1ms in do_nothing) I get the following: i=23 23.2 ms
i=24 24.9 ms
i=25 24.7 ms <--
i=26 27.0 ms
i=27 26.6 ms <--
i=28 28.4 ms
i=29 29.6 ms
i=30 30.7 ms
i=31 30.7 ms <--
i=32 33.0 ms |
|
That is a surprising result (which I can confirm); on STM32 in a similar test, the |
|
Luckily I found a solution to overcome the behaviour I described in this topic. It can be used if people need better resolution with the stock Micropython for the Esp32. await asyncio.sleep_ms(0) in async def do_nothing(), will do the trick. import asyncio
import time
async def do_nothing():
while True:
await asyncio.sleep_ms(0)
async def test():
for _ in range(100):
for i in range(1, 55):
start = time.ticks_us()
await asyncio.sleep_ms(i)
t = time.ticks_diff(time.ticks_us(), start)
print(f"i={i:2} {t/1000:.1f} ms")
asyncio.create_task(do_nothing())
asyncio.run(test())Some of the output: i=48 48.3 ms
i=49 49.3 ms
i=50 50.5 ms
i=51 51.4 ms
i=52 52.3 ms
i=53 53.2 ms
i=54 54.4 ms
i= 1 1.3 ms
i= 2 2.5 ms
i= 3 3.4 ms
i= 4 4.3 ms
i= 5 5.2 ms
i= 6 6.4 ms
i= 7 7.3 ms
i= 8 8.2 msIf you change the await asyncio.sleep_ms(0) in async def do_nothing() to asyncio.sleep_ms(1) or only use task test() the problem will appear again. i=20 29.0 ms
i=21 29.3 ms
i=22 29.6 ms
i=23 29.3 ms
i=24 29.3 ms
i=25 29.3 ms
i=26 29.3 ms
i=27 29.3 ms
i=28 29.3 ms
i=29 29.3 ms
i=30 39.0 ms
i=31 39.3 ms
i=32 39.6 ms
i=33 39.3 ms
i=34 39.3 ms
i=35 39.3 ms
i=36 39.3 ms
i=37 39.3 ms
i=38 39.3 ms
i=39 39.3 ms |
This is caused / limited by Espressif IDF default freertos tick rate.
Any time the async loop sleeps it release the current thread in freertos so other background tasks can be handled.
It turns out the default freertos tick rate is 100hz / 10ms so that's why it takes (at least) that long to get back to the the application thread.
https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/kconfig.html#config-freertos-hz
If your particular application actually needs more responsiveness than that it's generally safe to speed that tick rate up in a custom build to 1000hz / 1ms though I expect your power usage will go up too.