asyncio: Warning message when waiting for an Event set by AbstractLoop.add_reader

[Léo El Amri]

Hello list,

During my attempt to bring asyncio support to the multiprocessing Queue,
I found warning messages when executing my code with asyncio debug
logging enabled.

It seems that awaiting for an Event will make theses messages appears
after the second attempt to wait for the Event.

Here is a code sample to test this (47 lines long):

import asyncio
import threading
import os
import io
import time
import logging
logging.basicConfig()
logging.getLogger('asyncio').setLevel(logging.DEBUG)
fd1, fd2 = os.pipe() # (r, w)
loop = asyncio.get_event_loop()
event = asyncio.Event()
def readfd(fd, size):
buf = io.BytesIO()
handle = fd
remaining = size
while remaining > 0:
chunk = os.read(handle, remaining)
n = len(chunk)
if n == 0:
raise Exception()
buf.write(chunk)
remaining -= n
return buf.getvalue()
def f():
loop.add_reader(fd1, event.set)
loop.run_until_complete(g())
loop.close()
async def g():
while True:
await event.wait()
msg = readfd(fd1, 4)
event.clear()
if msg == b'STOP':
break
print(msg)
if __name__ == '__main__':
t = threading.Thread(target=f)
t.start()
time.sleep(1)
os.write(fd2, b'TST1')
time.sleep(1)
os.write(fd2, b'TST2')
time.sleep(1)
os.write(fd2, b'TST3')
time.sleep(1)
os.write(fd2, b'STOP')
t.join()

I get this output:

DEBUG:asyncio:Using selector: EpollSelector
DEBUG:asyncio:poll took 999.868 ms: 1 events
b'TST1'
b'TST2'
WARNING:asyncio:Executing <Handle [CUT] locks.py:261> took 1.001 seconds
INFO:asyncio:poll took 1000.411 ms: 1 events
b'TST3'
WARNING:asyncio:Executing <Handle [CUT] locks.py:261> took 1.001 seconds
DEBUG:asyncio:Close <_UnixSelectorEventLoop [CUT]>

I don't get the message, because it seems that the event is awaited
properly. I'm especially bugged, because I get this output from the
actual code I'm writing:

WARNING:asyncio:Executing <Handle [CUT] locks.py:261> took 1.000 seconds
DEBUG:asyncio:poll took 0.012 ms: 1 events

Here, it seems that "polling" went for 0.012 ms. But it should have gone
for 1000.0 ms. But in any case, it still works. However, the fact that
polling seems to "return" instantly is a strange fact.

The test code is not producing this difference. In fact, it seems that
polling is working as intended (Polling takes 1000.0 ms and Event is
awaited for 1000.0 ms). But there is still this warning...

Maybe one of you have an insight on this ?

[dieter]

Léo El Amri via Python-list <pytho...@python.org> writes:
> ...

> WARNING:asyncio:Executing <Handle [CUT] locks.py:261> took 1.000 seconds

> ...

> But there is still this warning...

At your place, I would look at the code responsible for the warning.
I assume that it is produced because the waiting time is rather
high -- but this is just a guess.

[Léo El Amri]

Thanks for the answer, but the problem is that this is happening in the
built-in Event of the asyncio package; which is actually a coroutine. I
don't expect the built-in to have this kind of behavior. I guess I'll
have to dig on the source code of the asyncio default loop to actually
understand how all the thing is behaving in the shadows. Maybe I'm
simply doing something wrong. But it would mean that the documentation
is lacking some details, or maybe that I'm just really stupid on this one.

[Léo El Amri]

I found out what was the problem.

The behavior of my "reader" (The callback passed to
AbstractEventLoop.add_reader()) is to set an event. This event is
awaited for in a coroutine which actually reads what is written on a
pipe. The execution flow is the following:

* NEW LOOP TURN
* The selector awaits for read-ready state on a file descriptor AND The
coroutine awaits for the event
* At some point, the file descriptor becomes read-ready, the selector
queue the callback to set the event on the loop
* The callback put on the queue is called and the event is set
* NEW LOOP TURN
* The selector awaits for read-ready state on a file descriptor AND The
coroutine awaits for the event
* The file descriptor is read-ready, so the selector queue the callback
to set the event on the loop
* The corouting is resumed, because the event is now set, the corouting
then reads what was written on the file descriptor, then clears the
event and awaits again for it
* The callback put on the queue is called and the event is set
* NEW LOOP TURN
* The selector awaits for read-ready state on a file descriptor AND The
coroutine awaits for the event
* The corouting is resumed, because the event was set at the end of the
last turn, so the coroutine attempts a read, but blocks on it, because
the file descriptor is actually not read-ready

Rince and repeat.

This behavior actually depends on how the loop is implemented. So the
best practice here is to actually do the read from the callback you
gives to AbstractEventLoop.add_reader(). I think we should put a mention
about it in the documentation.