Asyncio python with serial device occupies 100% processor

Question

When I run this small bulk from the rfxcom python library :

from asyncio import get_event_loop
from rfxcom.transport import AsyncioTransport

dev_name = '/dev/serial/by-id/usb-RFXCOM_RFXtrx433_A1XZI13O-if00-port0'
loop = get_event_loop()

def handler(packet):
    print(packet.data)

try:
    rfxcom = AsyncioTransport(dev_name, loop, callback=handler)
    loop.run_forever()
finally:
    loop.close()

I see that CPU usage is getting very high (around 100%). I don’t understand why: there are very few messages (~ 1 message every 5 seconds) received by the module, and I thought that when epoll_wait , then the CPU should be in standby mode, waiting for the next event.

I ran main with python cProfile and it shows this:

In [4]: s.sort_stats('time', 'module').print_stats(50)
Mon Jul 20 22:20:55 2015    rfxcom_profile.log

     263629453 function calls (263628703 primitive calls) in 145.437 seconds

   Ordered by: internal time, file name
   List reduced from 857 to 50 due to restriction <50>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
 13178675   37.280    0.000  141.337    0.000 /usr/local/lib/python3.4/asyncio/base_events.py:1076(_run_once)
 13178675   31.114    0.000   53.230    0.000 /usr/local/lib/python3.4/selectors.py:415(select)
 13178674   15.115    0.000   32.253    0.000 /usr/local/lib/python3.4/asyncio/selector_events.py:479(_process_events)
 13178675   12.582    0.000   12.582    0.000 {method 'poll' of 'select.epoll' objects}
 13178699   11.462    0.000   17.138    0.000 /usr/local/lib/python3.4/asyncio/base_events.py:1058(_add_callback)
 13178732    6.397    0.000   11.397    0.000 /usr/local/lib/python3.4/asyncio/events.py:118(_run)
 26359349    4.872    0.000    4.872    0.000 {built-in method isinstance}
        1    4.029    4.029  145.365  145.365 /usr/local/lib/python3.4/asyncio/base_events.py:267(run_forever)
 13178669    4.010    0.000    4.913    0.000 /home/bruno/src/DomoPyc/venv/lib/python3.4/site-packages/rfxcom-0.3.0-py3.4.egg/rfxcom/transport/asyncio.py:85(_writer)

So, the first three function calls within the past tense: python3.4/asyncio/base_events.py, python3.4/selectors.pyand python3.4/asyncio/selector_events.py.

EDIT : a time command on a similar run gives:

time python -m cProfile -o rfxcom_profile.log rfxcom_profile.py
real    2m24.548s
user    2m19.892s
sys     0m4.113s

Can someone explain to me why?

EDIT2. fonctions , , epoll_wait - 2ms:

// many lines like this :
epoll_wait(4, {{EPOLLOUT, {u32=7, u64=537553536922157063}}}, 2, -1) = 1    

base_event._run_once, , . , - , .

- ...

.

Answer 1

, .

PYTHONASYNCIODEBUG 1 , :

 DEBUG:asyncio:poll took 0.006 ms: 1 events

Rfxcom . , , ", , , ". , :

self.loop.call_soon(self.loop.add_writer, self.dev.fd, self._writer)

self.dev - Serial, self.dev.fd - .

doc "add_writer (fd, callback, * args): ".

, , script:

logger = logging.getLogger()
logger.setLevel(logging.DEBUG)

loop = get_event_loop()

def writer_cb():
    logger.info("writer cb called")

s = Serial('/dev/serial/by-id/usb-RFXCOM_RFXtrx433_A1XZI13O-if00-port0', 38400, timeout=1)

loop.add_writer(s.fd, writer_cb)
loop.run_forever()

, , CPU 100%:

DEBUG:asyncio:poll took 0.006 ms: 1 events
INFO:root:writer cb called

, , , write .