uasyncio not working #53

kevinkk525 · 2018-02-03T10:40:54Z

The uasyncio library is not working because of this problem:

Try running a code like this:

import uasyncio as asyncio
import machine

async def test():
    print("test")
    machine.idle()

loop=asyncio.get_event_loop()
loop.run_until_complete(test())

It is very simple but the test() coroutine is never entered and instead after a few seconds, the watchdog gets triggered:

Task watchdog got triggered. The following tasks did not reset the watchdog in time:
 - mp_task (CPU 0/1)
Tasks currently running:
CPU 0: IDLE
CPU 1: IDLE

So I got into debugging the issue and found, that the function utimeq.peektime() that is used inside the asyncio.wait() function (core.py line 71) for getting the delay to wait, is returning an incredibly high number leading to a very long poller.ipoll() triggering the watchdog.
This was the output:

>>> loop.run_until_complete(test())
DEBUG:uasyncio.core:Scheduling (88451, <generator object '_run_and_stop' at 3f8189e0>, ())
DEBUG:uasyncio:poll.wait(532638518)

As you can see the function utimeq.peektime() returns a huge number even before the coroutine is started, but it should return 0 (?) in the first iteration so self.wait() is not called yet as you can see in the following test on esp8266:

async def test():
    print("hi")
    await asyncio.sleep(1)
    print("ho")
loop.run_until_complete(test())
debug::Scheduling (110138, <generator object '_run_and_stop' at 3fff4b20>, ())
debug::Next coroutine to run: (110138, <generator object '_run_and_stop' at 3fff4b20>, ())
debug::Coroutine <generator object '_run_and_stop' at 3fff4b20> send args: ()
hi
debug::Coroutine <generator object '_run_and_stop' at 3fff4b20> yield result: 1000
debug::Scheduling (111170, <generator object '_run_and_stop' at 3fff4b20>, ())
debug::poll.wait(992)
debug::Next coroutine to run: (111170, <generator object '_run_and_stop' at 3fff4b20>, ())
debug::Coroutine <generator object '_run_and_stop' at 3fff4b20> send args: ()
ho
debug::Coroutine <generator object '_run_and_stop' at 3fff4b20> yield result: <StopLoop object at 3fff5380>

The function utimeq.peektime() in modutimeq.c is this:

STATIC mp_obj_t mod_utimeq_peektime(mp_obj_t heap_in) {
    mp_obj_utimeq_t *heap = get_heap(heap_in);
    if (heap->len == 0) {
        nlr_raise(mp_obj_new_exception_msg(&mp_type_IndexError, "empty heap"));
    }

    struct qentry *item = &heap->items[0];
    return MP_OBJ_NEW_SMALL_INT(item->time);
}
STATIC MP_DEFINE_CONST_FUN_OBJ_1(mod_utimeq_peektime_obj, mod_utimeq_peektime);

But that's where my knowledge ends, I have no idea why this function returns this huge number even before the coroutine is executed.

The text was updated successfully, but these errors were encountered:

mkarliner · 2018-02-03T12:06:11Z

I've the same problem.

loboris · 2018-02-03T12:19:39Z

The issue is caused by the fact that in my port the utime.time() returns the float value (as in standard Python time module).
utimeq.push() converts the 1st argument (time value) ti small integer (int value >> 1) which was causing the big number to be returned by peektime().

I have fixed this in modutimeq.c and it should now work as expected.
The update will be commited later today.

loboris · 2018-02-03T20:53:41Z

Update which should fix this issue is now committed.

kevinkk525 · 2018-02-03T21:21:28Z

Thanks a lot for the quick answer and the bugfix! Sadly it does not fix the problem:

>>> import logging
>>> log=logging.getLogger("")
>>> logging._level=0
>>> log.debug("hi")
DEBUG::hi
>>> from uasyncio import core
>>> core.set_debug(1)
>>> import uasyncio as asy
>>> asy.set_debug(1)
>>> async def test():
...     print("hi")
...     await asy.sleep(1)
...     print("ho")
>>> loop=asy.get_event_loop()
>>> loop.run_until_complete(test())
DEBUG:uasyncio.core:Scheduling (140599, <generator object '_run_and_stop' at 3f818600>, ())
DEBUG:uasyncio:poll.wait(532585938)

(sysname='esp32', nodename='esp32', release='3.1.15', version='ESP32_LoBo_v3.1.15 on 2017-02-03', machine='ESP32 board with ESP32')

loboris · 2018-02-03T21:35:00Z

It fixes the utimeq.peektime() issue.

>>> import time, utimeq
>>> lpq = utimeq.utimeq(42)
>>> lpq.push(time.time(), None, None)
>>> lpq.peektime()
111
>>>

I don't use asyincio, so I can't help, unless you point me to the module/method which causes the error.

kevinkk525 · 2018-02-03T21:36:22Z

You are right, can confirm your code. That's weird.. Thanks for your help!
I'll try to figure it out.

kevinkk525 · 2018-02-03T21:48:07Z

I figured it out and it is still the utimeq module:

>>> import utimeq
>>> import time
>>> time.ticks_ms()
243554
>>> lpq=utimeq.utimeq(42)
>>> lpq.push(time.ticks_ms(),None,None)
>>> lpq.peektime()
532726656

The asyncio library uses ticks_ms as a time reference, not the time.time()

loboris · 2018-02-03T22:07:52Z

It is strange.

>>> x = [0, 0, 0]
>>> a=time.ticks_ms()
>>> a
1836083
>>> lpq.push(a,None,None)
>>> lpq.peektime()
532717224
>>> lpq.pop(x)
>>> lpq.push(1836083,None,None)
>>> lpq.peektime()
1836083
>>> 
>>> type(a)
<class 'int'>
>>> type(1836083)
<class 'int'>
>>>

I'll check it tomorrow.

kevinkk525 · 2018-02-04T18:43:42Z

To add a little more insight:

>>> a=time.ticks_ms()
>>> a
1833843
>>> lpq.push(a,None,None)
>>> lpq.peektime()
532725904
>>> lpq.pop(x)
>>> lpq.push(int(float(a)),None,None)
>>> lpq.peektime()
1833843
>>> lpq.pop(x)
>>> int(float(a))==a
True

So apparently converting the input to float and back to int gets around the problem.
Implementing this workaround into the uasnycio.core file makes the library work as expected.
I guess that means that there is something wrong with the output (object) of time.ticks_ms()? I don't know much about the underlying C++ layer but I hope this helps finding the source of the problem as utimeq and utime library are surely used in many other libraries.

loboris · 2018-02-04T19:27:15Z

I've just committed an update which includes more changes to utimeq module,
Pushing any time value (including time.ticks_ms()) should now work as intended and value returned by peektime() should be correct (same as pushed).

kevinkk525 · 2018-02-04T19:36:33Z

Thanks a lot!
This commit fixed it. It now also works with time.ticks_us()

mkarliner · 2018-02-21T16:57:47Z

It's probably worth noting that if you use the uasyncio from PyPi, ie: install with upip, asyncio will not work, as this is an incompatible fork. If you want to use asyncio following the instructions here:
https://github.com/peterhinch/micropython-async/blob/master/TUTORIAL.md

kevinkk525 · 2018-02-21T17:31:41Z

It is incompatible with version 2.0 of uasyncio. Using version 1.4.2 works perfectly fine.
I do not install using upip, I download the modules I need and add it as frozen bytecode to my firmware build.

mkarliner · 2018-02-21T17:57:25Z

Sure. I just thought I'd leave an note for those that follow.

kevinkk525 mentioned this issue Feb 3, 2018

Hangs when reopening WiFi connection micropython/micropython-esp32#167

Closed

kevinkk525 closed this as completed Feb 4, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

uasyncio not working #53

uasyncio not working #53

kevinkk525 commented Feb 3, 2018 •

edited

Loading

mkarliner commented Feb 3, 2018

Uh oh!

loboris commented Feb 3, 2018 •

edited

Loading

Uh oh!

loboris commented Feb 3, 2018

Uh oh!

kevinkk525 commented Feb 3, 2018

Uh oh!

loboris commented Feb 3, 2018

Uh oh!

kevinkk525 commented Feb 3, 2018

Uh oh!

kevinkk525 commented Feb 3, 2018 •

edited

Loading

Uh oh!

loboris commented Feb 3, 2018

Uh oh!

kevinkk525 commented Feb 4, 2018

Uh oh!

loboris commented Feb 4, 2018

Uh oh!

kevinkk525 commented Feb 4, 2018

Uh oh!

mkarliner commented Feb 21, 2018

Uh oh!

kevinkk525 commented Feb 21, 2018

Uh oh!

mkarliner commented Feb 21, 2018

Uh oh!

uasyncio not working #53

uasyncio not working #53

Comments

kevinkk525 commented Feb 3, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

mkarliner commented Feb 3, 2018

Uh oh!

loboris commented Feb 3, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

loboris commented Feb 3, 2018

Uh oh!

kevinkk525 commented Feb 3, 2018

Uh oh!

loboris commented Feb 3, 2018

Uh oh!

kevinkk525 commented Feb 3, 2018

Uh oh!

kevinkk525 commented Feb 3, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

loboris commented Feb 3, 2018

Uh oh!

kevinkk525 commented Feb 4, 2018

Uh oh!

loboris commented Feb 4, 2018

Uh oh!

kevinkk525 commented Feb 4, 2018

Uh oh!

mkarliner commented Feb 21, 2018

Uh oh!

kevinkk525 commented Feb 21, 2018

Uh oh!

mkarliner commented Feb 21, 2018

Uh oh!

kevinkk525 commented Feb 3, 2018 •

edited

Loading

loboris commented Feb 3, 2018 •

edited

Loading

kevinkk525 commented Feb 3, 2018 •

edited

Loading