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