2

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?

2 Answers 2

2

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.

2
  • Thanks for the response. Now I know to keep searching. Do you have any suggestions on how to connect these calls back to their source within my application code? The generic nature of the stack traces leaves me in a guess-and-check debugging state.
    – MRocklin
    Jul 30, 2018 at 15:11
  • I don't have any tricks for this. Usually the culprit shows up pretty clearly in other profiles. If these two are taking 40% of cpu time, I'd expect to see whatever is calling them showing up at least 10% of the time. If not, maybe it's just a diffuse issue and there's not much to be done about it. Aug 1, 2018 at 0:20
0

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. 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.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.