Add asyncio monitoring hooks

[brettlangdon]

Thanks everyone for continuing to engage in this thread, means I am thinking about this problem a lot more lately.

in this case I’d probably reach for a custom task factory and/or a custom event loop

One thing I want to see us (observability vendors) move away from is all the monkey patching and custom pieces we have to do in order to get access to necessary observability data. The more of this we can either build into the runtime or push onto third party libraries (e.g. uvloop, flask, etc) then the more consistent, reliable, and (likely?) lower overhead our observability are going to be.

The main things I am trying to optimize for:

1. Trying to avoid any manual steps a user needs to take
   a. import my_library should be the most any user is required to do to enable instrumentation
   b. user’s manually needing to enable a task factory or custom event loop is a non-starter for us
2. Trying to ensure 100% compatibility with or without our library
   a. our user’s should not have to rely on our library being present in order for their application to work
   b. if a user is using a version of Python, a library, or event loop we don’t support, then things shouldn’t break
3. Observability vendors are compatible with each other
   a. when using multiple vendors, it is easy for us to step on each other’s toes (especially if we are adding wrappers ontop of wrappers, etc), or add more than necessary overhead when our instrumentation is compounded

We can (and do) handle most of this already today via safe/defensive/exhaustive programming, but… we can make things a lot easier for folks at the runtime (whether we are talking about only task monitoring or expanding more to “observability” on a whole). Can we make the experience of monitoring Python applications easier and more comprehensive for all users?

Also the OP proposal ( sys.set_async_monitoring_hooks ) feels very global.

But it still feels like it should be a hook on the event loop itself, not necessarily asyncio.

I think in practice folks use either the standard library event loop or uvloop. Have you considered exposing functions that wrap these two loops?

The more I think back on the POC I made, I don’t really love the API proposed for the hooks. It is clunky, and not very extensible if we ever needed to add more “hooks” into it. It has been enough to try and reason about what hooks points could be useful for my purposes.

I wonder if it is worth considering adding a “diagnostics” event bus to Python, similar to Diagnostics channel from Node.js or System.Diagnostics.Activity from .NET (“sort of” to both of them, loose concept, I’m not sure the same APIs/approach should be copied).

The goal being, if we have a similar bus to listen on for events either from the Python runtime or third party libraries (uvloop, etc). Then we don’t have to worry about either adding a hooks API (or monkey patching ) in a bunch of places or libraries. we can emit events on task enter/exit from either standard event loop, we can also add similar (or the exact same?) events to uvloop or other third party event loops to emit the event as well. Since “instrumentation” doesn’t really fit the goal/purpose of sys.audit, it is probably best to avoid re-using that same channel.

We do have to get event emitting added to a bunch of places, but a single interface for reading makes vendors be less invasive in a user’s application, easier to activate/disable, and make it easier to get access to new data without needing to implement more instrumentation by X number of vendors. For example, Flask uses Blinker to support their own lifecycle hooks, but if Blinker was “built into” the Python runtime then observability libraries will have an easier approach to monitoring. (I’d be willing be more than willing to contribute resources to contribute event emitting to open source Python packages for observability purposes, especially if there is a standard library “blessed” method for doing so).

[yoavdw (Yoav)]

@brettlangdon

I wonder if it is worth considering adding a “diagnostics” event bus to Python, similar to Diagnostics channel from Node.js or System.Diagnostics.Activity from .NET (“sort of” to both of them, loose concept, I’m not sure the same APIs/approach should be copied).

Aren’t audit events similar to this and could be used here?

[brettlangdon]

@yoavdw

Aren’t audit events similar to this and could be used here?

Yes… but I’ve been stressing over the semantics of “audit”. I didn’t want to assume that people would want more diagnostic type data to flow over that same channel.

If I were to propose task.enter / task.exit sys.audit events, does that fit enough to the originally intended purpose?(It definitely meets my needs, so I would be happy with it.)

[yoavdw (Yoav)]

According to @steve.dower (who authored the audit hooks PEP), in a very similar thread, yes:

@steve.dower

Using sys.audit to raise the event is probably best. Those are also intended to work like what you suggest, and are already used for collecting execution statistics (though not widely yet… I think DataDog uses/intends to use them).

[brettlangdon]

Great, yeah like I said I was probably putting too much semantic meaning around “audit” and didn’t want to assume.

That being said, seems like there are two main streams in this thread:

1. Does it make sense to add hooks into CPython for things like task enter/exit (myself and others would like this list to be longer, but listing just these two as an example/starting point)
2. What does the hooking API look like? Reusing sys.audit would be preferred interface over custom/bespoke hooking interface?

I would be more than happy to rewrite my POC using sys.audit if we wanted something concrete to discuss.

[yoavdw (Yoav)]

A concrete POC is always a great way to advance a discussion about an idea!

[brettlangdon]

Here is the new POC emitting sys.audit hooks.

Comparing python:main...brettlangdon:feat-asyncio-audit-hooks · python/cpython

Here is some sample usage:

import asyncio
import sys


def audit_hook(event, args):
    if not event.startswith("asyncio."):
        return

    print(event, args)


sys.addaudithook(audit_hook)


async def work():
    await asyncio.sleep(0.1)
    await asyncio.sleep(0.1)


async def main():
    await asyncio.gather(work(), work(), work())


if __name__ == "__main__":
    asyncio.run(main())

and output log:

❯ python sample.py
asyncio.task.register (<Task pending name='Task-1' coro=<main() running at /Users/brett.langdon/src/cpython/sample.py:20>>,)
asyncio.task.enter (<Task pending name='Task-1' coro=<main() running at /Users/brett.langdon/src/cpython/sample.py:20> cb=[_run_until_complete_cb() at /Users/brett.langdon/src/cpython/Lib/asyncio/base_events.py:182]>,)
asyncio.task.register (<Task pending name='Task-2' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:15>>,)
asyncio.task.register (<Task pending name='Task-3' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:15>>,)
asyncio.task.register (<Task pending name='Task-4' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:15>>,)
asyncio.task.leave (<Task pending name='Task-1' coro=<main() running at /Users/brett.langdon/src/cpython/sample.py:21> wait_for=<_GatheringFuture pending cb=[Task.task_wakeup()]> cb=[_run_until_complete_cb() at /Users/brett.langdon/src/cpython/Lib/asyncio/base_events.py:182]>,)
asyncio.task.enter (<Task pending name='Task-2' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:15> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task pending name='Task-2' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:16> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.enter (<Task pending name='Task-3' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:15> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task pending name='Task-3' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:16> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.enter (<Task pending name='Task-4' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:15> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task pending name='Task-4' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:16> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.enter (<Task pending name='Task-2' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:16> wait_for=<Future finished result=None> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task pending name='Task-2' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:17> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.enter (<Task pending name='Task-3' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:16> wait_for=<Future finished result=None> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task pending name='Task-3' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:17> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.enter (<Task pending name='Task-4' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:16> wait_for=<Future finished result=None> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task pending name='Task-4' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:17> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.enter (<Task pending name='Task-2' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:17> wait_for=<Future finished result=None> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task finished name='Task-2' coro=<work() done, defined at /Users/brett.langdon/src/cpython/sample.py:15> result=None>,)
asyncio.task.enter (<Task pending name='Task-3' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:17> wait_for=<Future finished result=None> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task finished name='Task-3' coro=<work() done, defined at /Users/brett.langdon/src/cpython/sample.py:15> result=None>,)
asyncio.task.enter (<Task pending name='Task-4' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:17> wait_for=<Future finished result=None> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task finished name='Task-4' coro=<work() done, defined at /Users/brett.langdon/src/cpython/sample.py:15> result=None>,)
asyncio.task.enter (<Task pending name='Task-1' coro=<main() running at /Users/brett.langdon/src/cpython/sample.py:21> wait_for=<_GatheringFuture finished result=[None, None, None]> cb=[_run_until_complete_cb() at /Users/brett.langdon/src/cpython/Lib/asyncio/base_events.py:182]>,)
asyncio.task.leave (<Task finished name='Task-1' coro=<main() done, defined at /Users/brett.langdon/src/cpython/sample.py:20> result=None>,)
asyncio.task.register (<Task pending name='Task-5' coro=<BaseEventLoop.shutdown_asyncgens() running at /Users/brett.langdon/src/cpython/Lib/asyncio/base_events.py:561>>,)
asyncio.task.enter (<Task pending name='Task-5' coro=<BaseEventLoop.shutdown_asyncgens() running at /Users/brett.langdon/src/cpython/Lib/asyncio/base_events.py:561> cb=[_run_until_complete_cb() at /Users/brett.langdon/src/cpython/Lib/asyncio/base_events.py:182]>,)
asyncio.task.leave (<Task finished name='Task-5' coro=<BaseEventLoop.shutdown_asyncgens() done, defined at /Users/brett.langdon/src/cpython/Lib/asyncio/base_events.py:561> result=None>,)
asyncio.task.register (<Task pending name='Task-6' coro=<BaseEventLoop.shutdown_default_executor() running at /Users/brett.langdon/src/cpython/Lib/asyncio/base_events.py:586>>,)
asyncio.task.enter (<Task pending name='Task-6' coro=<BaseEventLoop.shutdown_default_executor() running at /Users/brett.langdon/src/cpython/Lib/asyncio/base_events.py:586> cb=[_run_until_complete_cb() at /Users/brett.langdon/src/cpython/Lib/asyncio/base_events.py:182]>,)
asyncio.task.leave (<Task finished name='Task-6' coro=<BaseEventLoop.shutdown_default_executor() done, defined at /Users/brett.langdon/src/cpython/Lib/asyncio/base_events.py:586> result=None>,)

Here is another sample using uvloop:

import asyncio
import sys


def audit_hook(event, args):
    if not event.startswith("asyncio."):
        return

    print(event, args)


sys.addaudithook(audit_hook)


async def work():
    await asyncio.sleep(0.1)
    await asyncio.sleep(0.1)


async def main():
    await asyncio.gather(work(), work(), work())


if __name__ == "__main__":
    import uvloop

    uvloop.run(main())

    # also works with

    # with asyncio.Runner(loop_factory=uvloop.new_event_loop) as runner:
    #    runner.run(main())

    # and

    # uvloop.install()
    # asyncio.run(main())

❯ python sample.py
asyncio.task.register (<Task pending name='Task-1' coro=<run.<locals>.wrapper() running at /Users/brett.langdon/src/cpython/.venv/lib/python3.12/site-packages/uvloop/__init__.py:54>>,)
asyncio.task.enter (<Task pending name='Task-1' coro=<run.<locals>.wrapper() running at /Users/brett.langdon/src/cpython/.venv/lib/python3.12/site-packages/uvloop/__init__.py:54> cb=[run_until_complete.<locals>.done_cb()]>,)
asyncio.task.register (<Task pending name='Task-2' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:15>>,)
asyncio.task.register (<Task pending name='Task-3' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:15>>,)
asyncio.task.register (<Task pending name='Task-4' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:15>>,)
asyncio.task.leave (<Task pending name='Task-1' coro=<run.<locals>.wrapper() running at /Users/brett.langdon/src/cpython/.venv/lib/python3.12/site-packages/uvloop/__init__.py:61> wait_for=<_GatheringFuture pending cb=[Task.task_wakeup()]> cb=[run_until_complete.<locals>.done_cb()]>,)
asyncio.task.enter (<Task pending name='Task-2' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:15> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task pending name='Task-2' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:16> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.enter (<Task pending name='Task-3' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:15> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task pending name='Task-3' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:16> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.enter (<Task pending name='Task-4' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:15> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task pending name='Task-4' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:16> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.enter (<Task pending name='Task-2' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:16> wait_for=<Future finished result=None> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task pending name='Task-2' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:17> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.enter (<Task pending name='Task-3' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:16> wait_for=<Future finished result=None> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task pending name='Task-3' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:17> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.enter (<Task pending name='Task-4' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:16> wait_for=<Future finished result=None> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task pending name='Task-4' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:17> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.enter (<Task pending name='Task-2' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:17> wait_for=<Future finished result=None> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task finished name='Task-2' coro=<work() done, defined at /Users/brett.langdon/src/cpython/sample.py:15> result=None>,)
asyncio.task.enter (<Task pending name='Task-3' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:17> wait_for=<Future finished result=None> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task finished name='Task-3' coro=<work() done, defined at /Users/brett.langdon/src/cpython/sample.py:15> result=None>,)
asyncio.task.enter (<Task pending name='Task-4' coro=<work() running at /Users/brett.langdon/src/cpython/sample.py:17> wait_for=<Future finished result=None> cb=[gather.<locals>._done_callback() at /Users/brett.langdon/src/cpython/Lib/asyncio/tasks.py:767]>,)
asyncio.task.leave (<Task finished name='Task-4' coro=<work() done, defined at /Users/brett.langdon/src/cpython/sample.py:15> result=None>,)
asyncio.task.enter (<Task pending name='Task-1' coro=<run.<locals>.wrapper() running at /Users/brett.langdon/src/cpython/.venv/lib/python3.12/site-packages/uvloop/__init__.py:61> wait_for=<_GatheringFuture finished result=[None, None, None]> cb=[run_until_complete.<locals>.done_cb()]>,)
asyncio.task.leave (<Task finished name='Task-1' coro=<run.<locals>.wrapper() done, defined at /Users/brett.langdon/src/cpython/.venv/lib/python3.12/site-packages/uvloop/__init__.py:54> result=None>,)
asyncio.task.register (<Task pending name='Task-5' coro=<Loop.shutdown_asyncgens()>>,)
asyncio.task.enter (<Task pending name='Task-5' coro=<Loop.shutdown_asyncgens()> cb=[run_until_complete.<locals>.done_cb()]>,)
asyncio.task.leave (<Task finished name='Task-5' coro=<<iterable_coroutine without __name__>()> result=None>,)
asyncio.task.register (<Task pending name='Task-6' coro=<Loop.shutdown_default_executor()>>,)
asyncio.task.enter (<Task pending name='Task-6' coro=<Loop.shutdown_default_executor()> cb=[run_until_complete.<locals>.done_cb()]>,)
asyncio.task.leave (<Task finished name='Task-6' coro=<<iterable_coroutine without __name__>()> result=None>,)

[anon10000667]

Another argument in favor of providing some of these metrics is that NodeJS already exposes the async lag via perf_hooks.monitorEventLoopDelay, and this is the basis for the metrics semantic conventions that OpenTelemetry defined for NodeJS.

I followed Guido’s ideas of using a custom event loop and came up with the following POC that works both with asyncio and uvloop. Note that the POC is incomplete (missing call_at and probably is rough on the edges)

import asyncio
import time
import uvloop
import sys


def _format_cb(cb):
    task = getattr(cb, "__self__", None)
    if isinstance(task, asyncio.tasks.Task):
        # format the task
        return _get_coro_name(task._coro)
    else:
        return str(cb)


def _get_coro_name(coro):
    # Code adapted from asyncio.coroutines._format_coroutine
    coro_code = None
    if hasattr(coro, 'cr_code') and coro.cr_code:
        coro_code = coro.cr_code
    elif hasattr(coro, 'gi_code') and coro.gi_code:
        coro_code = coro.gi_code
    
    # If Cython's coroutine has a fake code object without proper
    # co_filename -- expose that.
    filename = coro_code.co_filename or '<empty co_filename>'

    # Coroutines compiled with Cython sometimes don't have
    # proper __qualname__ or __name__.  While that is a bug
    # in Cython, asyncio shouldn't crash with an AttributeError
    # in its __repr__ functions.
    if hasattr(coro, "__qualname__") and coro.__qualname__:
        coro_name = coro.__qualname__
    elif hasattr(coro, "__name__") and coro.__name__:
        coro_name = coro.__name__
    else:
        # Stop masking Cython bugs, expose them in a friendly way.
        coro_name = f"<{type(coro).__name__} without __name__>"
    return f"{coro_name} at {filename}"


def patched_loop(loop_class):
    class PatchedLoop(loop_class):
        def call_soon(self, callback, *args, context=None):
            def wrapped_callback(*args, **kwargs):
                t0 = time.monotonic_ns()
                try:
                    return callback(*args, **kwargs)
                finally:
                    delta = time.monotonic_ns() - t0
                    # TODO: decide the right threshold
                    if delta > 0:
                        print(f"{_format_cb(callback)} took {delta/1000000.0:.3}ms")

            super().call_soon(wrapped_callback, *args, context=context)

    return PatchedLoop

def test(task):
    asyncio.get_event_loop().run_until_complete(task)


async def cpu_intensive():
    s = 0
    for i in range(1_000_000):
        s += i**5
        s %= 37
    await asyncio.sleep(0.002)
    for i in range(1_000_000):
        s += i**5
        s %= 37


async def cpu_intensive2():
    await asyncio.gather(cpu_intensive(), cpu_intensive())


async def no_cpu():
    return 0

if __name__ == "__main__":
    policy_class = asyncio.DefaultEventLoopPolicy
    if len(sys.argv) == 2 and sys.argv[1] == "uvloop":
        print("Using uvloop")
        policy_class = uvloop.EventLoopPolicy

    new_loop_class = patched_loop(policy_class()._loop_factory().__class__)
    policy_class._loop_factory = new_loop_class
    asyncio.set_event_loop_policy(policy_class())

    loop = asyncio.new_event_loop()
    asyncio.set_event_loop(loop)

    test(cpu_intensive2())
    test(no_cpu())

which produces the output

Using uvloop
cpu_intensive2 at test_loop.py took 0.0378ms
cpu_intensive at test_loop.py took 2.77e+02ms
cpu_intensive at test_loop.py took 2.83e+02ms
cpu_intensive at test_loop.py took 2.75e+02ms
<function gather.<locals>._done_callback at 0x10ded6520> took 0.00739ms
cpu_intensive at test_loop.py took 2.84e+02ms
<function gather.<locals>._done_callback at 0x10ded6520> took 0.0207ms
cpu_intensive2 at test_loop.py took 0.0204ms
<cyfunction run_until_complete.<locals>.done_cb at 0x10de1a670> took 0.00678ms
no_cpu at test_loop.py took 0.00553ms
<cyfunction run_until_complete.<locals>.done_cb at 0x10de18c70> took 0.00557ms

Note that this strategy has the advantage of having access to the Task, which in principle would allow to record information about its execution flow. For example which blocking part of the async function we are recording about, which would aid in debugging slow blocking code.