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 | |
Zachary Ware | 5819cfa | 2015-01-06 00:40:43 -0600 | [diff] [blame] | 74 | The :ref:`Synchronization primitives <asyncio-sync>` section describes ways |
| 75 | to synchronize tasks. |
Victor Stinner | 606ab03 | 2014-02-01 03:18:58 +0100 | [diff] [blame] | 76 | |
Victor Stinner | 399c59d | 2015-01-09 01:32:02 +0100 | [diff] [blame] | 77 | The :ref:`Subprocess and threads <asyncio-subprocess-threads>` section lists |
| 78 | asyncio limitations to run subprocesses from different threads. |
| 79 | |
| 80 | |
| 81 | |
Victor Stinner | 606ab03 | 2014-02-01 03:18:58 +0100 | [diff] [blame] | 82 | |
Victor Stinner | 45b27ed | 2014-02-01 02:36:43 +0100 | [diff] [blame] | 83 | .. _asyncio-handle-blocking: |
| 84 | |
Eli Bendersky | b73c833 | 2014-02-09 06:07:47 -0800 | [diff] [blame] | 85 | Handle blocking functions correctly |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 86 | ----------------------------------- |
| 87 | |
| 88 | Blocking functions should not be called directly. For example, if a function |
| 89 | blocks for 1 second, other tasks are delayed by 1 second which can have an |
| 90 | important impact on reactivity. |
| 91 | |
| 92 | For networking and subprocesses, the :mod:`asyncio` module provides high-level |
Victor Stinner | 9592edb | 2014-02-02 15:03:02 +0100 | [diff] [blame] | 93 | APIs like :ref:`protocols <asyncio-protocol>`. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 94 | |
| 95 | An executor can be used to run a task in a different thread or even in a |
| 96 | 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] | 97 | :meth:`BaseEventLoop.run_in_executor` method. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 98 | |
Victor Stinner | 45b27ed | 2014-02-01 02:36:43 +0100 | [diff] [blame] | 99 | .. seealso:: |
| 100 | |
| 101 | The :ref:`Delayed calls <asyncio-delayed-calls>` section details how the |
| 102 | event loop handles time. |
| 103 | |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 104 | |
| 105 | .. _asyncio-logger: |
| 106 | |
Victor Stinner | 45b27ed | 2014-02-01 02:36:43 +0100 | [diff] [blame] | 107 | Logging |
| 108 | ------- |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 109 | |
Victor Stinner | 45b27ed | 2014-02-01 02:36:43 +0100 | [diff] [blame] | 110 | The :mod:`asyncio` module logs information with the :mod:`logging` module in |
| 111 | the logger ``'asyncio'``. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 112 | |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 113 | |
| 114 | .. _asyncio-coroutine-not-scheduled: |
| 115 | |
| 116 | Detect coroutine objects never scheduled |
| 117 | ---------------------------------------- |
| 118 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 119 | When a coroutine function is called and its result is not passed to |
Zachary Ware | 5819cfa | 2015-01-06 00:40:43 -0600 | [diff] [blame] | 120 | :func:`async` or to the :meth:`BaseEventLoop.create_task` method, the execution |
| 121 | of the coroutine object will never be scheduled which is probably a bug. |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 122 | :ref:`Enable the debug mode of asyncio <asyncio-debug-mode>` to :ref:`log a |
| 123 | warning <asyncio-logger>` to detect it. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 124 | |
| 125 | Example with the bug:: |
| 126 | |
| 127 | import asyncio |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 128 | |
| 129 | @asyncio.coroutine |
| 130 | def test(): |
| 131 | print("never scheduled") |
| 132 | |
| 133 | test() |
| 134 | |
| 135 | Output in debug mode:: |
| 136 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 137 | Coroutine test() at test.py:3 was never yielded from |
| 138 | Coroutine object created at (most recent call last): |
| 139 | File "test.py", line 7, in <module> |
| 140 | test() |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 141 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 142 | The fix is to call the :func:`async` function or the |
| 143 | :meth:`BaseEventLoop.create_task` method with the coroutine object. |
| 144 | |
| 145 | .. seealso:: |
| 146 | |
| 147 | :ref:`Pending task destroyed <asyncio-pending-task-destroyed>`. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 148 | |
| 149 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 150 | Detect exceptions never consumed |
| 151 | -------------------------------- |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 152 | |
| 153 | Python usually calls :func:`sys.displayhook` on unhandled exceptions. If |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 154 | :meth:`Future.set_exception` is called, but the exception is never consumed, |
Zachary Ware | 5819cfa | 2015-01-06 00:40:43 -0600 | [diff] [blame] | 155 | :func:`sys.displayhook` is not called. Instead, :ref:`a log is emitted |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 156 | <asyncio-logger>` when the future is deleted by the garbage collector, with the |
| 157 | traceback where the exception was raised. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 158 | |
| 159 | Example of unhandled exception:: |
| 160 | |
| 161 | import asyncio |
| 162 | |
| 163 | @asyncio.coroutine |
| 164 | def bug(): |
| 165 | raise Exception("not consumed") |
| 166 | |
| 167 | loop = asyncio.get_event_loop() |
| 168 | asyncio.async(bug()) |
| 169 | loop.run_forever() |
| 170 | |
| 171 | Output:: |
| 172 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 173 | Task exception was never retrieved |
Victor Stinner | ab1c853 | 2014-10-12 21:37:16 +0200 | [diff] [blame] | 174 | 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] | 175 | Traceback (most recent call last): |
Victor Stinner | ab1c853 | 2014-10-12 21:37:16 +0200 | [diff] [blame] | 176 | File "asyncio/tasks.py", line 237, in _step |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 177 | result = next(coro) |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 178 | File "asyncio/coroutines.py", line 141, in coro |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 179 | res = func(*args, **kw) |
Victor Stinner | ab1c853 | 2014-10-12 21:37:16 +0200 | [diff] [blame] | 180 | File "test.py", line 5, in bug |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 181 | raise Exception("not consumed") |
| 182 | Exception: not consumed |
| 183 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 184 | :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] | 185 | traceback where the task was created. Output in debug mode:: |
| 186 | |
| 187 | Task exception was never retrieved |
| 188 | future: <Task finished coro=<bug() done, defined at test.py:3> exception=Exception('not consumed',) created at test.py:8> |
| 189 | source_traceback: Object created at (most recent call last): |
| 190 | File "test.py", line 8, in <module> |
| 191 | asyncio.async(bug()) |
| 192 | Traceback (most recent call last): |
| 193 | File "asyncio/tasks.py", line 237, in _step |
| 194 | result = next(coro) |
| 195 | File "asyncio/coroutines.py", line 79, in __next__ |
| 196 | return next(self.gen) |
| 197 | File "asyncio/coroutines.py", line 141, in coro |
| 198 | res = func(*args, **kw) |
| 199 | File "test.py", line 5, in bug |
| 200 | raise Exception("not consumed") |
| 201 | Exception: not consumed |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 202 | |
Zachary Ware | 5819cfa | 2015-01-06 00:40:43 -0600 | [diff] [blame] | 203 | There are different options to fix this issue. The first option is to chain the |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 204 | coroutine in another coroutine and use classic try/except:: |
| 205 | |
| 206 | @asyncio.coroutine |
| 207 | def handle_exception(): |
| 208 | try: |
| 209 | yield from bug() |
| 210 | except Exception: |
| 211 | print("exception consumed") |
| 212 | |
| 213 | loop = asyncio.get_event_loop() |
| 214 | asyncio.async(handle_exception()) |
| 215 | loop.run_forever() |
| 216 | |
| 217 | Another option is to use the :meth:`BaseEventLoop.run_until_complete` |
| 218 | function:: |
| 219 | |
| 220 | task = asyncio.async(bug()) |
| 221 | try: |
| 222 | loop.run_until_complete(task) |
| 223 | except Exception: |
| 224 | print("exception consumed") |
| 225 | |
Zachary Ware | 5819cfa | 2015-01-06 00:40:43 -0600 | [diff] [blame] | 226 | .. seealso:: |
| 227 | |
| 228 | The :meth:`Future.exception` method. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 229 | |
| 230 | |
Zachary Ware | 5819cfa | 2015-01-06 00:40:43 -0600 | [diff] [blame] | 231 | Chain coroutines correctly |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 232 | -------------------------- |
| 233 | |
| 234 | When a coroutine function calls other coroutine functions and tasks, they |
Eli Bendersky | 679688e | 2014-01-20 08:13:31 -0800 | [diff] [blame] | 235 | should be chained explicitly with ``yield from``. Otherwise, the execution is |
| 236 | not guaranteed to be sequential. |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 237 | |
Eli Bendersky | 679688e | 2014-01-20 08:13:31 -0800 | [diff] [blame] | 238 | Example with different bugs using :func:`asyncio.sleep` to simulate slow |
| 239 | operations:: |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 240 | |
| 241 | import asyncio |
| 242 | |
| 243 | @asyncio.coroutine |
| 244 | def create(): |
| 245 | yield from asyncio.sleep(3.0) |
| 246 | print("(1) create file") |
| 247 | |
| 248 | @asyncio.coroutine |
| 249 | def write(): |
| 250 | yield from asyncio.sleep(1.0) |
| 251 | print("(2) write into file") |
| 252 | |
| 253 | @asyncio.coroutine |
| 254 | def close(): |
| 255 | print("(3) close file") |
| 256 | |
| 257 | @asyncio.coroutine |
| 258 | def test(): |
| 259 | asyncio.async(create()) |
| 260 | asyncio.async(write()) |
| 261 | asyncio.async(close()) |
| 262 | yield from asyncio.sleep(2.0) |
| 263 | loop.stop() |
| 264 | |
| 265 | loop = asyncio.get_event_loop() |
| 266 | asyncio.async(test()) |
| 267 | loop.run_forever() |
| 268 | print("Pending tasks at exit: %s" % asyncio.Task.all_tasks(loop)) |
Victor Stinner | f40c663 | 2014-01-28 23:32:40 +0100 | [diff] [blame] | 269 | loop.close() |
Victor Stinner | db39a0d | 2014-01-16 18:58:01 +0100 | [diff] [blame] | 270 | |
| 271 | Expected output:: |
| 272 | |
| 273 | (1) create file |
| 274 | (2) write into file |
| 275 | (3) close file |
| 276 | Pending tasks at exit: set() |
| 277 | |
| 278 | Actual output:: |
| 279 | |
| 280 | (3) close file |
| 281 | (2) write into file |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 282 | Pending tasks at exit: {<Task pending create() at test.py:7 wait_for=<Future pending cb=[Task._wakeup()]>>} |
| 283 | Task was destroyed but it is pending! |
| 284 | 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] | 285 | |
| 286 | The loop stopped before the ``create()`` finished, ``close()`` has been called |
| 287 | before ``write()``, whereas coroutine functions were called in this order: |
| 288 | ``create()``, ``write()``, ``close()``. |
| 289 | |
| 290 | To fix the example, tasks must be marked with ``yield from``:: |
| 291 | |
| 292 | @asyncio.coroutine |
| 293 | def test(): |
| 294 | yield from asyncio.async(create()) |
| 295 | yield from asyncio.async(write()) |
| 296 | yield from asyncio.async(close()) |
| 297 | yield from asyncio.sleep(2.0) |
| 298 | loop.stop() |
| 299 | |
| 300 | Or without ``asyncio.async()``:: |
| 301 | |
| 302 | @asyncio.coroutine |
| 303 | def test(): |
| 304 | yield from create() |
| 305 | yield from write() |
| 306 | yield from close() |
| 307 | yield from asyncio.sleep(2.0) |
| 308 | loop.stop() |
| 309 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 310 | |
| 311 | .. _asyncio-pending-task-destroyed: |
| 312 | |
| 313 | Pending task destroyed |
| 314 | ---------------------- |
| 315 | |
| 316 | If a pending task is destroyed, the execution of its wrapped :ref:`coroutine |
| 317 | <coroutine>` did not complete. It is probably a bug and so a warning is logged. |
| 318 | |
| 319 | Example of log:: |
| 320 | |
| 321 | Task was destroyed but it is pending! |
Victor Stinner | ab1c853 | 2014-10-12 21:37:16 +0200 | [diff] [blame] | 322 | 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] | 323 | |
| 324 | :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] | 325 | traceback where the task was created. Example of log in debug mode:: |
| 326 | |
| 327 | Task was destroyed but it is pending! |
| 328 | source_traceback: Object created at (most recent call last): |
| 329 | File "test.py", line 15, in <module> |
| 330 | task = asyncio.async(coro, loop=loop) |
| 331 | 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> |
| 332 | |
Victor Stinner | 530ef2f | 2014-07-08 12:39:10 +0200 | [diff] [blame] | 333 | |
| 334 | .. seealso:: |
| 335 | |
| 336 | :ref:`Detect coroutine objects never scheduled <asyncio-coroutine-not-scheduled>`. |
| 337 | |