async python logging details of AbstractEventLoop.slow_callback_duration

Question

I'm getting the following warnings in my python 3.6 code using:

import os
os.environ['PYTHONASYNCIODEBUG'] = '1'

Executing <Handle <TaskWakeupMethWrapper object at 0x7fa8653dca08>(<Future finis...events.py:295>) created at /opt/rh/rh-python36/root/usr/lib64/python3.6/asyncio/tasks.py:390> took 5.012 seconds
Executing <Handle <TaskWakeupMethWrapper object at 0x7fa8653dcc48>(<Future finis...events.py:295>) created at /opt/rh/rh-python36/root/usr/lib64/python3.6/asyncio/tasks.py:390> took 9.941 seconds
Executing <Handle <TaskWakeupMethWrapper object at 0x7fa8653dca08>(<Future finis...events.py:295>) created at /opt/rh/rh-python36/root/usr/lib64/python3.6/asyncio/tasks.py:390> took 5.038 seconds

So this is useful because I know things are being slow - but I'm having trouble figuring out if there is a way to get a better stack trace so I can actually track down what is happening.

Is there a way to get more of a stack trace out of this - I assume its triggering the AbstractEventLoop.slow_callback_duration as described here: https://docs.python.org/3.6/library/asyncio-dev.html

Thanks

Denis Otkidach · Accepted Answer · 2020-07-13 18:52:50Z

Don't you mind dirty tricks, do you? There are some hints:

Replace asyncio.base_events._format_handle with your own handle, a function with one argument, let's call it handle.
Look at handle._source_traceback, it might give you information where your task in originated from.
Take a look at handle._callback. In your case it's TaskWakeupMethWrapper, but there can be other alternatives.
TaskWakeupMethWrapper exposes nothin to public, but who can stop a true hacker?

There is a code to unwrap it with ctypes:

PyObject_HEAD = [
    ('ob_refcnt', ctypes.c_size_t),
    ('ob_type', ctypes.c_void_p),
]

class TaskWakeupMethWrapper_Structure(ctypes.Structure):
    _fields_ = PyObject_HEAD + [
        ('ww_task', ctypes.py_object),
    ]


class PyAsyncGenASend_Structure(ctypes.Structure):
    _fields_ = PyObject_HEAD + [
        ('ags_gen', ctypes.py_object),
        ('ags_sendval', ctypes.py_object),
        ('ags_state', ctypes.c_int),
    ]


def unwrap_task_wakeup_method(wrapper: 'TaskWakeupMethWrapper'):
    wrapper_p = ctypes.cast(
        ctypes.c_void_p(id(wrapper)),
        ctypes.POINTER(TaskWakeupMethWrapper_Structure),
    )
    return wrapper_p.contents.ww_task

Print the state of unwrapped coroutine (e.g. with inspect.getcoroutinestate()). Note, that the state is after slow code, so be ready to see just CORO_CLOSED.

akozlu · Accepted Answer · 2020-07-11 00:31:36Z

0


async def monitor_tasks():
    while True:
        tasks = [t for t in asyncio.all_tasks() if t is not asyncio.current_task()]
        [t.print_stack(limit=5) for t in tasks]
        await asyncio.sleep(2)

loop = asyncio.get_event_loop()  # Start main event loop.
loop.create_task(monitor_tasks()) # To monitor stack trace

This is how I prefer to do it. You can print the stack trace with python's logging module.

Taken from this great tutorial

answered Jul 11, 2020 at 0:31

akozlu

1119 bronze badges

Collectives™ on Stack Overflow

async python logging details of AbstractEventLoop.slow_callback_duration

2 Answers 2

Comments

Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

2 Answers 2

Comments

Comments

Your Answer

Sign up or log in

Post as a guest

Related