CODEWITHSUNDEEP
pythonpython-asyncio
HoverHell
HoverHell

Reputation: 4889

asyncio: warn about long-running handlers

With asyncio, to keep latency low, coroutines should not take a long time in between yielding.

To ensure that, logging the long runs might be useful.

A runnable example demonstrating what I mean:

#!/usr/bin/env python3

import time
from time import monotonic_ns
import asyncio
from pyaux.runlib import init_logging
init_logging(level=1)

state = {}


class LoggyLoopMixin:
    _warn_run_once_time = 0.2

    def _run_once(self):
        start_time = monotonic_ns()
        result = super()._run_once()
        end_time = monotonic_ns()
        self._check_run_once_time_diff(start_time=start_time, end_time=end_time)

    def _check_run_once_time_diff(self, start_time, end_time):
        time_diff = (end_time - start_time) / 1e9
        if time_diff > self._warn_run_once_time:
            self._handle_run_once_time_diff(time_diff=time_diff)

    def _handle_run_once_time_diff(self, time_diff, **kwargs):
        print("WARNING: large run_once time difference: %.3fs" % (time_diff,))


def mixin_asyncio_loop(mixin_cls):
    superclass = asyncio.get_event_loop_policy().__class__

    # assuming that `superclass._loop_factory` is a class.
    # pylint: disable=protected-access
    class MixinnedEventLoop(mixin_cls, superclass._loop_factory):
        """ ... """

    class MixinnedEventLoopPolicy(superclass):
        _loop_factory = MixinnedEventLoop

    elp = MixinnedEventLoopPolicy()
    asyncio.set_event_loop_policy(elp)
    return elp


mixin_asyncio_loop(LoggyLoopMixin)


async def heartbeat(sleep_time=0.1, warn_time=0.2):
    """
    An on-top-of-the-loop implementation, which is even worse.
    See: https://github.com/pebble/event-loop-lag
    """
    prev = monotonic_ns()
    warn_time_ns = int(warn_time * 1e9)
    while True:
        now = monotonic_ns()
        if now - prev > warn_time_ns:
            print("Hearbeat missed (%.3fs from last)" % ((now - prev) / 1e9,))
        else:
            print("Heartbeat time: %d" % (now - prev,))
        prev = monotonic_ns()
        await asyncio.sleep(sleep_time)


async def amain():
    # asyncio.ensure_future(heartbeat())

    sleep_time = 0.01
    while sleep_time < 3.5:
        print("Busy for %.3fs" % (sleep_time,))
        # await asyncio.sleep(sleep_time)
        time.sleep(sleep_time)
        await asyncio.sleep(0.001)  # yield at all
        sleep_time *= 1.5


def main():
    loop = asyncio.get_event_loop()
    loop.run_until_complete(amain())


if __name__ == '__main__':
    main()

However, I expected there to be already existing implementations of it, and it feels like I've seen this feature before, but could not find it.

And, as it has been noted elsewhere, subclassing asyncio is discouraged.

Are there existing implementations of this feature?

Upvotes: 4

Views: 664

Answers (1)

Mikhail Gerasimov
Mikhail Gerasimov

Reputation: 39546

Are there existing implementations of this feature?

Yes, it's a debug mode of event loop.

Change your code following way to see result:

loop = asyncio.get_event_loop()
loop.set_debug(True)
loop.run_until_complete(amain())

You'll see something like this:

Busy for 0.034s
Busy for 0.051s
Busy for 0.076s
Busy for 0.114s
Executing <Handle ...> took 0.125 seconds
Busy for 0.171s
Executing <Handle ...> took 0.172 seconds
Busy for 0.256s
Executing <Handle ...> took 0.282 seconds
Busy for 0.384s

Upvotes: 2

Related Questions