qasync icon indicating copy to clipboard operation
qasync copied to clipboard

Add slow_callback_duration logging

Open kormax opened this issue 1 year ago • 0 comments

This PR resolves an issue encountered in #100 by adding functionality for logging slow handle._run invocations the same way it's done by asyncio.BaseEventLoop(events.AbstractEventLoop).

It the modifies _SimpleTimer.timerEvent function by adding handle invocation time tracking in case debug mode is enabled, tightly mimicking the code from asyncio.base_events.

Results of this change can be compared by running the following code:

1.1. asyncio plain code

# Test asyncio example

import asyncio
import time


async def main():
    time.sleep(1)  # Block event loop


if __name__ == "__main__":
    loop = asyncio.get_event_loop()
    loop.set_debug(True)  # Enable debug
    loop.slow_callback_duration = 0.1
    loop.run_until_complete(main())

1.2. asyncio plain result

Executing <Task finished name='Task-1' coro=<main() done, defined at /Users/username/Documents/qasync_demo.py/blocking_timer_asyncio.py:5> result=None created at /lib/python3.8/asyncio/base_events.py:595> took 1.005 seconds

2.1. qasync code

# Qasync loop example


import time

from qtpy.QtGui import QGuiApplication
from qasync import QEventLoop


async def main():
    time.sleep(1)  # Block event loop

if __name__ == "__main__":
    app = QGuiApplication([])
    loop = QEventLoop(app)
    loop.set_debug(True)  # Enable debug
    loop.slow_callback_duration = 0.1
    loop.run_until_complete(main())

2.2. qasync result

Executing <Task finished name='Task-1' coro=<main() done, defined at /Users/username/Documents/qasync_demo.py/blocking_timer_qasync.py:7> result=None created at /Users/username/Documents/qasync/qasync/__init__.py:415> took 1.001 seconds

P.S. The _current_handle is set during debug handle invocations in order to improve logging in case asyncio.BaseEventLoop.default_exception_handler is set as an exception handler and an exception occurs. It's not mandatory for this change, but is nice to have, considering it's set in the same part of the code.

kormax avatar Mar 17 '24 12:03 kormax