p4l1ly
commented
3 years ago Using the version 1.0 of yappi, the following simple example conveniently shows 0.5s of time when the event loop is blocked by main, spawn_blocking_sleep and blocking_sleep. (But I don't understand why 0.5s is not in the tsub of blocking_sleep since time.sleep is not in the list). But the current version of yappi would show 1.6s in main and 0.6s in spawn_blocking_sleep, which sums up the awaiting time with the blocking time and thus does not indicate the presence of incorrect sleep.
import asyncio
import time
import yappi
def blocking_sleep():
time.sleep(0.5)
async def spawn_blocking_sleep():
await asyncio.sleep(0.1)
blocking_sleep()
async def main():
await spawn_blocking_sleep()
await asyncio.sleep(1)
yappi.stop()
yappi.clear_stats()
yappi.set_clock_type("WALL")
yappi.start()
asyncio.run(main())
yappi.get_func_stats().print_all(
columns={0: ("name", 100), 1: ("ncall", 10), 2: ("tsub", 10), 3: ("ttot", 10), 4: ("tavg", 10)},
)Clock type: WALL
Ordered by: totaltime, desc
name ncall tsub ttot tavg
/home/paly/.pyenv/versions/3.8.6/lib/python3.8/asyncio/runners.py:8 run 1 0.000075 1.604799 1.604799
../versions/3.8.6/lib/python3.8/asyncio/base_events.py:580 _UnixSelectorEventLoop.run_until_complete 2 0.000111 1.603679 0.801839
../.pyenv/versions/3.8.6/lib/python3.8/asyncio/base_events.py:557 _UnixSelectorEventLoop.run_forever 2 0.000096 1.603399 0.801700
..y/.pyenv/versions/3.8.6/lib/python3.8/asyncio/base_events.py:1784 _UnixSelectorEventLoop._run_once 8 0.000408 1.603237 0.200405
/home/paly/.pyenv/versions/3.8.6/lib/python3.8/selectors.py:451 EpollSelector.select 8 0.000111 1.101044 0.137630
/home/paly/.pyenv/versions/3.8.6/lib/python3.8/asyncio/events.py:79 Handle._run 8 0.000074 0.501648 0.062706
aioblock.py:12 main 3 0.000050 0.501080 0.167027
aioblock.py:8 spawn_blocking_sleep 2 0.000023 0.500832 0.250416
aioblock.py:5 blocking_sleep 1 0.000018 0.500661 0.500661
..me/paly/.pyenv/versions/3.8.6/lib/python3.8/asyncio/unix_events.py:57 _UnixSelectorEventLoop.close 1 0.000028 0.000560 0.000560
..aly/.pyenv/versions/3.8.6/lib/python3.8/asyncio/selector_events.py:87 _UnixSelectorEventLoop.close 1 0.000096 0.000530 0.000530
..versions/3.8.6/lib/python3.8/asyncio/selector_events.py:98 _UnixSelectorEventLoop._close_self_pipe 1 0.000069 0.000353 0.000353
etc.
The v1.0 behaviour for coroutines was actually useful to detect incorrect use of non-asyncio I/O calls which block the loop but not CPU. It might be convenient to add an option to switch to the old behaviour (if it is not a big deal). Of course, using the old version of yappi is still an option for users but not as elegant as would be a switch.