带有串行设备的 asyncio python 占用 100% CPU答案

【问题标题】：asyncio python with serial device takes 100% CPU带有串行设备的 asyncio python 占用 100% CPU
【发布时间】：2015-07-20 21:19:20
【问题描述】：

当我从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()

我看到 CPU 使用率变得非常高（大约 100%）。我不明白为什么：模块收到的消息很少（每 5 秒 1 条消息），我认为当调用 epoll_wait 时 CPU 应该处于空闲状态，等待下一个事件。

我用 python cProfile 启动了 main，它显示了这个：

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)

所以前三个函数调用在经过时间方面是python3.4/asyncio/base_events.py、python3.4/selectors.py和python3.4/asyncio/selector_events.py。

编辑：类似运行的时间命令给出：

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

谁能解释一下为什么？

EDIT2：由于函数调用的次数非常多，所以我做了一个进程，发现epoll_wait上有一个循环，有一个超时值2毫秒：

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

我在 base_event._run_once 中看到计算了超时，但我无法弄清楚。我不知道如何将此超时设置得更高以降低 CPU。

如果有人有线索...

感谢您的回答。

【问题讨论】：

它大部分时间都花在select，这并不奇怪，因为这基本上是在事件之间休眠。在 Unixy 系统上，命令 time 可以显示进程是 I/O 受限还是 CPU 受限。它的输出将有助于诊断此问题。
谢谢凯文，是的，我没有想到时间命令。我要编辑问题

标签： python epoll python-asyncio

【解决方案1】：

我回答我的问题，因为它可能对其他人有用。

将环境变量PYTHONASYNCIODEBUG设置为1后，出现了如下几行：

 DEBUG:asyncio:poll took 0.006 ms: 1 events

在 Rfxcom 库中，有一个写入器机制，带有一个将数据推送到串行设备的队列。我的意图是“asyncio，告诉我什么时候可以写，然后我会刷新写队列”。所以有这样一行：

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

self.dev 是Serial 类实例，self.dev.fd 是串行文件描述符。

作为the doc says “add_writer(fd, callback, *args) : 开始观察文件描述符的写入可用性”。

我认为串口设备总是可以用来写的，所以我做了一个小脚本：

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。

【讨论】：