understanding Python asyncio profiler output

Question

I'm trying to understand the output of Python profiler while running Python asyncio based program:

I can see that my program is spending ~67% of time trying to acquire a thread lock.

1. Is this normal in asyncio programs? My application is single-threaded, I am not deferring any work to worker threads and logging minimally to console.

2. My app spends ~21% in select call. Does this roughly mean that 20% of run-time is spent idle (waiting for an event or callback to happen)?

Answer 1

The problem with profiling asyncio applications is that when coroutines context switch, you will not see them in the stack and you might have hard time figuring out which function is actually time is spent. In your case, you are probably seeing the asyncio event loop's own functions.(not sure without seeing the output of course.)

I would definitely suggest yappi. By version 1.2.1, it can natively profile coroutines and tell you exactly how much wall or cpu time is spent inside a coroutine.

See here for details on this coroutine profiling.

Answer 2

Looks like you are using debugger that collects data from all threads. Waiting for condition variable acquiring means an idle waiting in thread pool for new tasks.

Time spent in select means again idle waiting, but in this case it's waiting for network activity.