asyncio.sleep_ms(1) takes 10 msec to finish on esp32

[jomasnash]

Board : Esp-wroom-32 (tested on 2 boards)
Micropython 1.23 (problem also exists on 1.22

The following code should print a message every second but it takes about 10 seconds on the esp32.
If I run the same code on a esp8266 the prints come every second (as it should be).

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?

[bulletmark]

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:

$ micropython tmp.py 
1154 msecs
1143 msecs
1151 msecs
1150 msecs
..

which is about what you would expect. Ran it on my ESP32 and ESP32-S3 and got:

>> 2024-08-04 10:06:09 starting tmp.py as tmp.mpy
9982 msecs
9999 msecs
10000 msecs
10000 msecs
..

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.

[steveh127]

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.

[jomasnash]

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.

[steveh127]

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

[andrewleech]

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.

[shariltumin]

Thank you Andrew! I learned something new today.

Now after rebuilding a firmware with

CONFIG_FREERTOS_HZ=1000

in sdkconfig.board

I got the results I expected

MicroPython v1.24.0-preview.112.g154813297.dirty on 2024-08-04; ESP32 ASYNCIO (KAKI5-NTNG) with ESP32
>>> import test_asleep
1000 msecs
1000 msecs
1000 msecs
1000 msecs
1000 msecs
1000 msecs
1000 msecs
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "test_asleep.py", line 12, in <module>
  File "asyncio/core.py", line 1, in run
  File "asyncio/core.py", line 1, in run_until_complete
  File "asyncio/core.py", line 1, in wait_io_event
KeyboardInterrupt: 

This may be useful information for others.

[Josverl]

For sure this would be a useful note in the documentation. Either in uasync or slerp_ms.

[peterhinch]

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.

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 await call hands control to the scheduler which then allows each other pending task to run. Each task runs until it issues an await (or yields to the scheduler by other means). When each pending task has had its turn, control returns to the line of code after the sleep_ms. Typically this will take longer than 1ms. How much longer is entirely application dependent.

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.

[peterhinch]

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

[jomasnash]

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.

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.

await asyncio.sleep_ms(50)
is best understood as "pause for a minimum of 50ms". The instruction.

It can be less (tested on Esp32, esp8266 and RP-pico)

asyncio on ESP32 is far from useless. There are a number of substantial applications and libraries using it.

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.

[peterhinch]

It can be less (tested on Esp32, esp8266 and RP-pico)

If this is the case it is a bug (in my opinion). I suggest you produce a repro and raise an issue.

[jomasnash]

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

[peterhinch]

That is a surprising result (which I can confirm); on STM32 in a similar test, the sleep_ms always terminated early, by up to 400μs. I have raised #15626 - I'll be interested to see the maintainers' comments.

[jomasnash]

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 ms

If 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