Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 1 | .. currentmodule:: asyncio |
| 2 | |
Victor Stinner | 0f3e6bc | 2014-02-19 23:15:02 +0100 | [diff] [blame] | 3 | .. _asyncio-dev: |
| 4 | |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 5 | Develop with asyncio |
| 6 | ==================== |
| 7 | |
| 8 | Asynchronous programming is different than classical "sequential" programming. |
Eli Bendersky | 679688e | 2014-01-20 08:13:31 -0800 | [diff] [blame] | 9 | This page lists common traps and explains how to avoid them. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 10 | |
| 11 | |
Victor Stinner | 62511fd | 2014-06-23 00:36:11 +0200 | [diff] [blame] | 12 | .. _asyncio-debug-mode: |
| 13 | |
| 14 | Debug mode of asyncio |
| 15 | --------------------- |
| 16 | |
| 17 | To enable the debug mode globally, set the environment variable |
Victor Stinner | d71dcbb | 2014-08-25 17:04:12 +0200 | [diff] [blame] | 18 | :envvar:`PYTHONASYNCIODEBUG` to ``1``. To see debug traces, set the log level |
| 19 | of the :ref:`asyncio logger <asyncio-logger>` to :py:data:`logging.DEBUG`. The |
| 20 | simplest configuration is:: |
| 21 | |
| 22 | import logging |
| 23 | # ... |
| 24 | logging.basicConfig(level=logging.DEBUG) |
| 25 | |
| 26 | Examples of effects of the debug mode: |
Victor Stinner | 62511fd | 2014-06-23 00:36:11 +0200 | [diff] [blame] | 27 | |
| 28 | * Log :ref:`coroutines defined but never "yielded from" |
| 29 | <asyncio-coroutine-not-scheduled>` |
| 30 | * :meth:`~BaseEventLoop.call_soon` and :meth:`~BaseEventLoop.call_at` methods |
| 31 | raise an exception if they are called from the wrong thread. |
| 32 | * Log the execution time of the selector |
| 33 | * Log callbacks taking more than 100 ms to be executed. The |
| 34 | :attr:`BaseEventLoop.slow_callback_duration` attribute is the minimum |
| 35 | duration in seconds of "slow" callbacks. |
| 36 | |
| 37 | .. seealso:: |
| 38 | |
| 39 | The :meth:`BaseEventLoop.set_debug` method and the :ref:`asyncio logger |
| 40 | <asyncio-logger>`. |
| 41 | |
| 42 | |
Victor Stinner | 606ab03 | 2014-02-01 03:18:58 +0100 | [diff] [blame] | 43 | .. _asyncio-multithreading: |
| 44 | |
| 45 | Concurrency and multithreading |
| 46 | ------------------------------ |
| 47 | |
| 48 | An event loop runs in a thread and executes all callbacks and tasks in the same |
Victor Stinner | 86516d9 | 2014-02-18 09:22:00 +0100 | [diff] [blame] | 49 | thread. While a task is running in the event loop, no other task is running in |
Victor Stinner | 5cb84ed | 2014-02-04 18:18:27 +0100 | [diff] [blame] | 50 | the same thread. But when the task uses ``yield from``, the task is suspended |
| 51 | and the event loop executes the next task. |
Victor Stinner | 606ab03 | 2014-02-01 03:18:58 +0100 | [diff] [blame] | 52 | |
Victor Stinner | 5cb84ed | 2014-02-04 18:18:27 +0100 | [diff] [blame] | 53 | To schedule a callback from a different thread, the |
| 54 | :meth:`BaseEventLoop.call_soon_threadsafe` method should be used. Example to |
Guido van Rossum | 3c9bb69 | 2014-02-04 13:49:34 -0800 | [diff] [blame] | 55 | schedule a coroutine from a different thread:: |
Victor Stinner | 5cb84ed | 2014-02-04 18:18:27 +0100 | [diff] [blame] | 56 | |
| 57 | loop.call_soon_threadsafe(asyncio.async, coro_func()) |
Victor Stinner | 606ab03 | 2014-02-01 03:18:58 +0100 | [diff] [blame] | 58 | |
Victor Stinner | 790202d | 2014-02-07 19:03:05 +0100 | [diff] [blame] | 59 | Most asyncio objects are not thread safe. You should only worry if you access |
| 60 | objects outside the event loop. For example, to cancel a future, don't call |
| 61 | directly its :meth:`Future.cancel` method, but:: |
| 62 | |
| 63 | loop.call_soon_threadsafe(fut.cancel) |
| 64 | |
Victor Stinner | 606ab03 | 2014-02-01 03:18:58 +0100 | [diff] [blame] | 65 | To handle signals and to execute subprocesses, the event loop must be run in |
| 66 | the main thread. |
| 67 | |
| 68 | The :meth:`BaseEventLoop.run_in_executor` method can be used with a thread pool |
| 69 | executor to execute a callback in different thread to not block the thread of |
| 70 | the event loop. |
| 71 | |
| 72 | .. seealso:: |
| 73 | |
| 74 | See the :ref:`Synchronization primitives <asyncio-sync>` section to |
| 75 | synchronize tasks. |
| 76 | |
| 77 | |
Victor Stinner | 45b27ed | 2014-02-01 02:36:43 +0100 | [diff] [blame] | 78 | .. _asyncio-handle-blocking: |
| 79 | |
Eli Bendersky | b73c833 | 2014-02-09 06:07:47 -0800 | [diff] [blame] | 80 | Handle blocking functions correctly |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 81 | ----------------------------------- |
| 82 | |
| 83 | Blocking functions should not be called directly. For example, if a function |
| 84 | blocks for 1 second, other tasks are delayed by 1 second which can have an |
| 85 | important impact on reactivity. |
| 86 | |
| 87 | For networking and subprocesses, the :mod:`asyncio` module provides high-level |
Victor Stinner | 9592edb | 2014-02-02 15:03:02 +0100 | [diff] [blame] | 88 | APIs like :ref:`protocols <asyncio-protocol>`. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 89 | |
| 90 | An executor can be used to run a task in a different thread or even in a |
| 91 | different process, to not block the thread of the event loop. See the |
Victor Stinner | 606ab03 | 2014-02-01 03:18:58 +0100 | [diff] [blame] | 92 | :meth:`BaseEventLoop.run_in_executor` method. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 93 | |
Victor Stinner | 45b27ed | 2014-02-01 02:36:43 +0100 | [diff] [blame] | 94 | .. seealso:: |
| 95 | |
| 96 | The :ref:`Delayed calls <asyncio-delayed-calls>` section details how the |
| 97 | event loop handles time. |
| 98 | |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 99 | |
| 100 | .. _asyncio-logger: |
| 101 | |
Victor Stinner | 45b27ed | 2014-02-01 02:36:43 +0100 | [diff] [blame] | 102 | Logging |
| 103 | ------- |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 104 | |
Victor Stinner | 45b27ed | 2014-02-01 02:36:43 +0100 | [diff] [blame] | 105 | The :mod:`asyncio` module logs information with the :mod:`logging` module in |
| 106 | the logger ``'asyncio'``. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 107 | |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 108 | |
| 109 | .. _asyncio-coroutine-not-scheduled: |
| 110 | |
| 111 | Detect coroutine objects never scheduled |
| 112 | ---------------------------------------- |
| 113 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 114 | When a coroutine function is called and its result is not passed to |
| 115 | :func:`async` or to the :meth:`BaseEventLoop.create_task` method: the execution |
| 116 | of the coroutine objet will never be scheduled and it is probably a bug. |
| 117 | :ref:`Enable the debug mode of asyncio <asyncio-debug-mode>` to :ref:`log a |
| 118 | warning <asyncio-logger>` to detect it. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 119 | |
| 120 | Example with the bug:: |
| 121 | |
| 122 | import asyncio |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 123 | |
| 124 | @asyncio.coroutine |
| 125 | def test(): |
| 126 | print("never scheduled") |
| 127 | |
| 128 | test() |
| 129 | |
| 130 | Output in debug mode:: |
| 131 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 132 | Coroutine test() at test.py:3 was never yielded from |
| 133 | Coroutine object created at (most recent call last): |
| 134 | File "test.py", line 7, in <module> |
| 135 | test() |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 136 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 137 | The fix is to call the :func:`async` function or the |
| 138 | :meth:`BaseEventLoop.create_task` method with the coroutine object. |
| 139 | |
| 140 | .. seealso:: |
| 141 | |
| 142 | :ref:`Pending task destroyed <asyncio-pending-task-destroyed>`. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 143 | |
| 144 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 145 | Detect exceptions never consumed |
| 146 | -------------------------------- |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 147 | |
| 148 | Python usually calls :func:`sys.displayhook` on unhandled exceptions. If |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 149 | :meth:`Future.set_exception` is called, but the exception is never consumed, |
| 150 | :func:`sys.displayhook` is not called. Instead, a :ref:`a log is emitted |
| 151 | <asyncio-logger>` when the future is deleted by the garbage collector, with the |
| 152 | traceback where the exception was raised. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 153 | |
| 154 | Example of unhandled exception:: |
| 155 | |
| 156 | import asyncio |
| 157 | |
| 158 | @asyncio.coroutine |
| 159 | def bug(): |
| 160 | raise Exception("not consumed") |
| 161 | |
| 162 | loop = asyncio.get_event_loop() |
| 163 | asyncio.async(bug()) |
| 164 | loop.run_forever() |
| 165 | |
| 166 | Output:: |
| 167 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 168 | Task exception was never retrieved |
Victor Stinner | ab1c853 | 2014-10-12 21:37:16 +0200 | [diff] [blame] | 169 | future: <Task finished coro=<coro() done, defined at asyncio/coroutines.py:139> exception=Exception('not consumed',)> |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 170 | Traceback (most recent call last): |
Victor Stinner | ab1c853 | 2014-10-12 21:37:16 +0200 | [diff] [blame] | 171 | File "asyncio/tasks.py", line 237, in _step |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 172 | result = next(coro) |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 173 | File "asyncio/coroutines.py", line 141, in coro |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 174 | res = func(*args, **kw) |
Victor Stinner | ab1c853 | 2014-10-12 21:37:16 +0200 | [diff] [blame] | 175 | File "test.py", line 5, in bug |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 176 | raise Exception("not consumed") |
| 177 | Exception: not consumed |
| 178 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 179 | :ref:`Enable the debug mode of asyncio <asyncio-debug-mode>` to get the |
Victor Stinner | ab1c853 | 2014-10-12 21:37:16 +0200 | [diff] [blame] | 180 | traceback where the task was created. Output in debug mode:: |
| 181 | |
| 182 | Task exception was never retrieved |
| 183 | future: <Task finished coro=<bug() done, defined at test.py:3> exception=Exception('not consumed',) created at test.py:8> |
| 184 | source_traceback: Object created at (most recent call last): |
| 185 | File "test.py", line 8, in <module> |
| 186 | asyncio.async(bug()) |
| 187 | Traceback (most recent call last): |
| 188 | File "asyncio/tasks.py", line 237, in _step |
| 189 | result = next(coro) |
| 190 | File "asyncio/coroutines.py", line 79, in __next__ |
| 191 | return next(self.gen) |
| 192 | File "asyncio/coroutines.py", line 141, in coro |
| 193 | res = func(*args, **kw) |
| 194 | File "test.py", line 5, in bug |
| 195 | raise Exception("not consumed") |
| 196 | Exception: not consumed |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 197 | |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 198 | There are different options to fix this issue. The first option is to chain to |
| 199 | coroutine in another coroutine and use classic try/except:: |
| 200 | |
| 201 | @asyncio.coroutine |
| 202 | def handle_exception(): |
| 203 | try: |
| 204 | yield from bug() |
| 205 | except Exception: |
| 206 | print("exception consumed") |
| 207 | |
| 208 | loop = asyncio.get_event_loop() |
| 209 | asyncio.async(handle_exception()) |
| 210 | loop.run_forever() |
| 211 | |
| 212 | Another option is to use the :meth:`BaseEventLoop.run_until_complete` |
| 213 | function:: |
| 214 | |
| 215 | task = asyncio.async(bug()) |
| 216 | try: |
| 217 | loop.run_until_complete(task) |
| 218 | except Exception: |
| 219 | print("exception consumed") |
| 220 | |
| 221 | See also the :meth:`Future.exception` method. |
| 222 | |
| 223 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 224 | Chain correctly coroutines |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 225 | -------------------------- |
| 226 | |
| 227 | When a coroutine function calls other coroutine functions and tasks, they |
Eli Bendersky | 679688e | 2014-01-20 08:13:31 -0800 | [diff] [blame] | 228 | should be chained explicitly with ``yield from``. Otherwise, the execution is |
| 229 | not guaranteed to be sequential. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 230 | |
Eli Bendersky | 679688e | 2014-01-20 08:13:31 -0800 | [diff] [blame] | 231 | Example with different bugs using :func:`asyncio.sleep` to simulate slow |
| 232 | operations:: |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 233 | |
| 234 | import asyncio |
| 235 | |
| 236 | @asyncio.coroutine |
| 237 | def create(): |
| 238 | yield from asyncio.sleep(3.0) |
| 239 | print("(1) create file") |
| 240 | |
| 241 | @asyncio.coroutine |
| 242 | def write(): |
| 243 | yield from asyncio.sleep(1.0) |
| 244 | print("(2) write into file") |
| 245 | |
| 246 | @asyncio.coroutine |
| 247 | def close(): |
| 248 | print("(3) close file") |
| 249 | |
| 250 | @asyncio.coroutine |
| 251 | def test(): |
| 252 | asyncio.async(create()) |
| 253 | asyncio.async(write()) |
| 254 | asyncio.async(close()) |
| 255 | yield from asyncio.sleep(2.0) |
| 256 | loop.stop() |
| 257 | |
| 258 | loop = asyncio.get_event_loop() |
| 259 | asyncio.async(test()) |
| 260 | loop.run_forever() |
| 261 | print("Pending tasks at exit: %s" % asyncio.Task.all_tasks(loop)) |
Victor Stinner | f40c663 | 2014-01-28 23:32:40 +0100 | [diff] [blame] | 262 | loop.close() |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 263 | |
| 264 | Expected output:: |
| 265 | |
| 266 | (1) create file |
| 267 | (2) write into file |
| 268 | (3) close file |
| 269 | Pending tasks at exit: set() |
| 270 | |
| 271 | Actual output:: |
| 272 | |
| 273 | (3) close file |
| 274 | (2) write into file |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 275 | Pending tasks at exit: {<Task pending create() at test.py:7 wait_for=<Future pending cb=[Task._wakeup()]>>} |
| 276 | Task was destroyed but it is pending! |
| 277 | task: <Task pending create() done at test.py:5 wait_for=<Future pending cb=[Task._wakeup()]>> |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 278 | |
| 279 | The loop stopped before the ``create()`` finished, ``close()`` has been called |
| 280 | before ``write()``, whereas coroutine functions were called in this order: |
| 281 | ``create()``, ``write()``, ``close()``. |
| 282 | |
| 283 | To fix the example, tasks must be marked with ``yield from``:: |
| 284 | |
| 285 | @asyncio.coroutine |
| 286 | def test(): |
| 287 | yield from asyncio.async(create()) |
| 288 | yield from asyncio.async(write()) |
| 289 | yield from asyncio.async(close()) |
| 290 | yield from asyncio.sleep(2.0) |
| 291 | loop.stop() |
| 292 | |
| 293 | Or without ``asyncio.async()``:: |
| 294 | |
| 295 | @asyncio.coroutine |
| 296 | def test(): |
| 297 | yield from create() |
| 298 | yield from write() |
| 299 | yield from close() |
| 300 | yield from asyncio.sleep(2.0) |
| 301 | loop.stop() |
| 302 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 303 | |
| 304 | .. _asyncio-pending-task-destroyed: |
| 305 | |
| 306 | Pending task destroyed |
| 307 | ---------------------- |
| 308 | |
| 309 | If a pending task is destroyed, the execution of its wrapped :ref:`coroutine |
| 310 | <coroutine>` did not complete. It is probably a bug and so a warning is logged. |
| 311 | |
| 312 | Example of log:: |
| 313 | |
| 314 | Task was destroyed but it is pending! |
Victor Stinner | ab1c853 | 2014-10-12 21:37:16 +0200 | [diff] [blame] | 315 | task: <Task pending coro=<kill_me() done, defined at test.py:5> wait_for=<Future pending cb=[Task._wakeup()]>> |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 316 | |
| 317 | :ref:`Enable the debug mode of asyncio <asyncio-debug-mode>` to get the |
Victor Stinner | ab1c853 | 2014-10-12 21:37:16 +0200 | [diff] [blame] | 318 | traceback where the task was created. Example of log in debug mode:: |
| 319 | |
| 320 | Task was destroyed but it is pending! |
| 321 | source_traceback: Object created at (most recent call last): |
| 322 | File "test.py", line 15, in <module> |
| 323 | task = asyncio.async(coro, loop=loop) |
| 324 | task: <Task pending coro=<kill_me() done, defined at test.py:5> wait_for=<Future pending cb=[Task._wakeup()] created at test.py:7> created at test.py:15> |
| 325 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 326 | |
| 327 | .. seealso:: |
| 328 | |
| 329 | :ref:`Detect coroutine objects never scheduled <asyncio-coroutine-not-scheduled>`. |
| 330 | |