[FIXED] Which functions are free when profiling Tornado/Asyncio?

Issue

I'm running a fairly complex Tornado TCP server application and I'd like to understand what's taking time so that I can improve performance. I'm using Tornado v5+, so Tornado is backed by asyncio.

I run a statistical profiler on my event loop thread and find that stacks like the following are common:

tornado/ioloop.py::run_sync
asyncio/asyncio.py::start
asyncio/base_events.py::run_forever
asyncio/base_events.py::_run_once
asyncio/events.py::_run
torando/ioloop.py::<lambda>
torando/platform/asyncio.py::add_callback
asyncio/base_events.py::call_soon_threadsafe
asyncio/selector_events.py::_write_to_self
    csock.send(b'\0')

and

tornado/ioloop.py::run_sync
asyncio/asyncio.py::start
asyncio/base_events.py::run_forever
asyncio/base_events.py::_run_once
asyncio/events.py::selector_events.py::_read_from_self
    data = self._ssock_recv(4096)

These take up about 40% of compute time, both when active and when quiet. Should I be concerned about them, or are these just waiting states while the system waits for something to happen?

Solution

These two stack always occur in matched pairs whenever IOLoop.add_callback is used. It's not an idle state, it's overhead, and it's not expected for it to take up 40% of the time. The other 60% of the time should give you a clue about what's going on. It sounds to me like maybe you've got some sort of infinite loop or something running an infinite series of coroutines.

Answered By - Ben Darnell