2014-01-16 13:58:01 -04:00
|
|
|
.. currentmodule:: asyncio
|
|
|
|
|
2014-02-19 18:15:02 -04:00
|
|
|
.. _asyncio-dev:
|
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
=======================
|
|
|
|
Developing with asyncio
|
|
|
|
=======================
|
2014-01-16 13:58:01 -04:00
|
|
|
|
2018-09-17 20:16:44 -03:00
|
|
|
Asynchronous programming is different from classic "sequential"
|
2018-09-14 20:57:11 -03:00
|
|
|
programming.
|
|
|
|
|
|
|
|
This page lists common mistakes and traps and explains how
|
|
|
|
to avoid them.
|
2014-01-16 13:58:01 -04:00
|
|
|
|
|
|
|
|
2014-06-22 19:36:11 -03:00
|
|
|
.. _asyncio-debug-mode:
|
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
Debug Mode
|
|
|
|
==========
|
2014-06-22 19:36:11 -03:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
By default asyncio runs in production mode. In order to ease
|
|
|
|
the development asyncio has a *debug mode*.
|
2017-11-20 11:14:07 -04:00
|
|
|
|
2018-09-17 20:16:44 -03:00
|
|
|
There are several ways to enable asyncio debug mode:
|
2017-11-20 11:14:07 -04:00
|
|
|
|
2018-09-17 20:16:44 -03:00
|
|
|
* Setting the :envvar:`PYTHONASYNCIODEBUG` environment variable to ``1``.
|
2014-06-22 19:36:11 -03:00
|
|
|
|
2018-09-17 20:16:44 -03:00
|
|
|
* Using the :option:`-X` ``dev`` Python command line option.
|
2014-06-22 19:36:11 -03:00
|
|
|
|
2018-09-17 20:16:44 -03:00
|
|
|
* Passing ``debug=True`` to :func:`asyncio.run`.
|
2014-06-22 19:36:11 -03:00
|
|
|
|
2018-09-17 20:16:44 -03:00
|
|
|
* Calling :meth:`loop.set_debug`.
|
|
|
|
|
|
|
|
In addition to enabling the debug mode, consider also:
|
2015-01-29 19:55:58 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
* setting the log level of the :ref:`asyncio logger <asyncio-logger>` to
|
|
|
|
:py:data:`logging.DEBUG`, for example the following snippet of code
|
|
|
|
can be run at startup of the application::
|
2015-01-29 19:55:58 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
logging.basicConfig(level=logging.DEBUG)
|
2015-01-29 19:55:58 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
* configuring the :mod:`warnings` module to display
|
|
|
|
:exc:`ResourceWarning` warnings. One way of doing that is by
|
2018-09-17 20:16:44 -03:00
|
|
|
using the :option:`-W` ``default`` command line option.
|
2015-01-29 19:55:58 -04:00
|
|
|
|
|
|
|
|
2018-09-17 20:16:44 -03:00
|
|
|
When the debug mode is enabled:
|
2015-01-29 19:55:58 -04:00
|
|
|
|
2018-09-17 20:16:44 -03:00
|
|
|
* asyncio checks for :ref:`coroutines that were not awaited
|
|
|
|
<asyncio-coroutine-not-scheduled>` and logs them; this mitigates
|
|
|
|
the "forgotten await" pitfall.
|
2015-01-29 19:55:58 -04:00
|
|
|
|
2018-10-26 14:14:04 -03:00
|
|
|
* Many non-threadsafe asyncio APIs (such as :meth:`loop.call_soon` and
|
2018-09-14 20:57:11 -03:00
|
|
|
:meth:`loop.call_at` methods) raise an exception if they are called
|
|
|
|
from a wrong thread.
|
2015-01-29 19:55:58 -04:00
|
|
|
|
2018-09-17 20:16:44 -03:00
|
|
|
* The execution time of the I/O selector is logged if it takes too long to
|
|
|
|
perform an I/O operation.
|
2018-09-14 20:57:11 -03:00
|
|
|
|
2018-09-17 20:16:44 -03:00
|
|
|
* Callbacks taking longer than 100ms are logged. The
|
|
|
|
:attr:`loop.slow_callback_duration` attribute can be used to set the
|
|
|
|
minimum execution duration in seconds that is considered "slow".
|
2015-01-29 19:55:58 -04:00
|
|
|
|
|
|
|
|
2014-01-31 22:18:58 -04:00
|
|
|
.. _asyncio-multithreading:
|
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
Concurrency and Multithreading
|
|
|
|
==============================
|
2014-01-31 22:18:58 -04:00
|
|
|
|
2018-09-11 13:54:40 -03:00
|
|
|
An event loop runs in a thread (typically the main thread) and executes
|
2018-09-14 20:57:11 -03:00
|
|
|
all callbacks and Tasks in its thread. While a Task is running in the
|
|
|
|
event loop, no other Tasks can run in the same thread. When a Task
|
|
|
|
executes an ``await`` expression, the running Task gets suspended, and
|
|
|
|
the event loop executes the next Task.
|
|
|
|
|
|
|
|
To schedule a callback from a different OS thread, the
|
2018-09-11 13:54:40 -03:00
|
|
|
:meth:`loop.call_soon_threadsafe` method should be used. Example::
|
2014-02-04 13:18:27 -04:00
|
|
|
|
2015-10-05 20:20:00 -03:00
|
|
|
loop.call_soon_threadsafe(callback, *args)
|
2014-01-31 22:18:58 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
Almost all asyncio objects are not thread safe, which is typically
|
|
|
|
not a problem unless there is code that works with them from outside
|
|
|
|
of a Task or a callback. If there's a need for such code to call a
|
|
|
|
low-level asyncio API, the :meth:`loop.call_soon_threadsafe` method
|
|
|
|
should be used, e.g.::
|
2014-02-07 14:03:05 -04:00
|
|
|
|
|
|
|
loop.call_soon_threadsafe(fut.cancel)
|
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
To schedule a coroutine object from a different OS thread, the
|
2015-10-05 20:20:00 -03:00
|
|
|
:func:`run_coroutine_threadsafe` function should be used. It returns a
|
|
|
|
:class:`concurrent.futures.Future` to access the result::
|
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
async def coro_func():
|
|
|
|
return await asyncio.sleep(1, 42)
|
2014-01-31 22:18:58 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
# Later in another OS thread:
|
2014-01-31 22:18:58 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
future = asyncio.run_coroutine_threadsafe(coro_func(), loop)
|
|
|
|
# Wait for the result:
|
|
|
|
result = future.result()
|
2015-01-08 20:32:02 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
To handle signals and to execute subprocesses, the event loop must be
|
|
|
|
run in the main thread.
|
2015-01-08 20:32:02 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
The :meth:`loop.run_in_executor` method can be used with a
|
|
|
|
:class:`concurrent.futures.ThreadPoolExecutor` to execute
|
|
|
|
blocking code in a different OS thread without blocking the OS thread
|
|
|
|
that the event loop runs in.
|
2015-01-08 20:32:02 -04:00
|
|
|
|
2014-01-31 22:18:58 -04:00
|
|
|
|
2014-01-31 21:36:43 -04:00
|
|
|
.. _asyncio-handle-blocking:
|
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
Running Blocking Code
|
|
|
|
=====================
|
2014-01-16 13:58:01 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
Blocking (CPU-bound) code should not be called directly. For example,
|
|
|
|
if a function performs a CPU-intensive calculation for 1 second,
|
|
|
|
all concurrent asyncio Tasks and IO operations would be delayed
|
|
|
|
by 1 second.
|
2014-01-16 13:58:01 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
An executor can be used to run a task in a different thread or even in
|
2019-09-04 03:04:09 -03:00
|
|
|
a different process to avoid blocking the OS thread with the
|
2018-09-14 20:57:11 -03:00
|
|
|
event loop. See the :meth:`loop.run_in_executor` method for more
|
|
|
|
details.
|
2014-01-16 13:58:01 -04:00
|
|
|
|
|
|
|
|
2014-01-31 21:36:43 -04:00
|
|
|
.. _asyncio-logger:
|
|
|
|
|
|
|
|
Logging
|
2018-09-14 20:57:11 -03:00
|
|
|
=======
|
2014-01-16 13:58:01 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
asyncio uses the :mod:`logging` module and all logging is performed
|
|
|
|
via the ``"asyncio"`` logger.
|
2016-10-13 17:56:40 -03:00
|
|
|
|
2018-09-17 20:16:44 -03:00
|
|
|
The default log level is :py:data:`logging.INFO`, which can be easily
|
2018-09-14 20:57:11 -03:00
|
|
|
adjusted::
|
2016-10-13 17:56:40 -03:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
logging.getLogger("asyncio").setLevel(logging.WARNING)
|
2016-10-13 17:56:40 -03:00
|
|
|
|
2014-01-16 13:58:01 -04:00
|
|
|
|
|
|
|
.. _asyncio-coroutine-not-scheduled:
|
|
|
|
|
2018-09-17 20:16:44 -03:00
|
|
|
Detect never-awaited coroutines
|
2018-09-14 20:57:11 -03:00
|
|
|
===============================
|
2014-01-16 13:58:01 -04:00
|
|
|
|
2018-09-17 20:16:44 -03:00
|
|
|
When a coroutine function is called, but not awaited
|
|
|
|
(e.g. ``coro()`` instead of ``await coro()``)
|
|
|
|
or the coroutine is not scheduled with :meth:`asyncio.create_task`, asyncio
|
|
|
|
will emit a :exc:`RuntimeWarning`::
|
2014-01-16 13:58:01 -04:00
|
|
|
|
|
|
|
import asyncio
|
|
|
|
|
2017-12-11 11:35:49 -04:00
|
|
|
async def test():
|
2014-01-16 13:58:01 -04:00
|
|
|
print("never scheduled")
|
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
async def main():
|
|
|
|
test()
|
|
|
|
|
|
|
|
asyncio.run(main())
|
|
|
|
|
|
|
|
Output::
|
|
|
|
|
|
|
|
test.py:7: RuntimeWarning: coroutine 'test' was never awaited
|
2014-01-16 13:58:01 -04:00
|
|
|
test()
|
|
|
|
|
|
|
|
Output in debug mode::
|
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
test.py:7: RuntimeWarning: coroutine 'test' was never awaited
|
|
|
|
Coroutine created at (most recent call last)
|
|
|
|
File "../t.py", line 9, in <module>
|
|
|
|
asyncio.run(main(), debug=True)
|
|
|
|
|
|
|
|
< .. >
|
2014-01-16 13:58:01 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
File "../t.py", line 7, in main
|
|
|
|
test()
|
|
|
|
test()
|
2014-01-16 13:58:01 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
The usual fix is to either await the coroutine or call the
|
|
|
|
:meth:`asyncio.create_task` function::
|
2014-07-08 07:39:10 -03:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
async def main():
|
|
|
|
await test()
|
2014-01-16 13:58:01 -04:00
|
|
|
|
2014-07-08 07:39:10 -03:00
|
|
|
|
2018-09-17 20:16:44 -03:00
|
|
|
Detect never-retrieved exceptions
|
|
|
|
=================================
|
2014-01-16 13:58:01 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
If a :meth:`Future.set_exception` is called but the Future object is
|
|
|
|
never awaited on, the exception would never be propagated to the
|
|
|
|
user code. In this case, asyncio would emit a log message when the
|
|
|
|
Future object is garbage collected.
|
2014-01-16 13:58:01 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
Example of an unhandled exception::
|
2014-01-16 13:58:01 -04:00
|
|
|
|
|
|
|
import asyncio
|
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
async def bug():
|
2014-01-16 13:58:01 -04:00
|
|
|
raise Exception("not consumed")
|
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
async def main():
|
|
|
|
asyncio.create_task(bug())
|
|
|
|
|
|
|
|
asyncio.run(main())
|
2014-01-16 13:58:01 -04:00
|
|
|
|
|
|
|
Output::
|
|
|
|
|
2014-07-08 07:39:10 -03:00
|
|
|
Task exception was never retrieved
|
2018-09-14 20:57:11 -03:00
|
|
|
future: <Task finished coro=<bug() done, defined at test.py:3>
|
|
|
|
exception=Exception('not consumed')>
|
2014-10-12 16:37:16 -03:00
|
|
|
|
2014-01-16 13:58:01 -04:00
|
|
|
Traceback (most recent call last):
|
2018-09-14 20:57:11 -03:00
|
|
|
File "test.py", line 4, in bug
|
2014-01-16 13:58:01 -04:00
|
|
|
raise Exception("not consumed")
|
|
|
|
Exception: not consumed
|
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
:ref:`Enable the debug mode <asyncio-debug-mode>` to get the
|
|
|
|
traceback where the task was created::
|
2014-01-16 13:58:01 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
asyncio.run(main(), debug=True)
|
2014-01-16 13:58:01 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
Output in debug mode::
|
2016-07-26 06:18:21 -03:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
Task exception was never retrieved
|
|
|
|
future: <Task finished coro=<bug() done, defined at test.py:3>
|
|
|
|
exception=Exception('not consumed') created at asyncio/tasks.py:321>
|
2014-10-12 16:37:16 -03:00
|
|
|
|
2014-07-08 07:39:10 -03:00
|
|
|
source_traceback: Object created at (most recent call last):
|
2018-09-14 20:57:11 -03:00
|
|
|
File "../t.py", line 9, in <module>
|
|
|
|
asyncio.run(main(), debug=True)
|
2014-07-08 07:39:10 -03:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
< .. >
|
2015-01-29 20:35:14 -04:00
|
|
|
|
2018-09-14 20:57:11 -03:00
|
|
|
Traceback (most recent call last):
|
|
|
|
File "../t.py", line 4, in bug
|
|
|
|
raise Exception("not consumed")
|
|
|
|
Exception: not consumed
|