blob: 8ec2ff09141cc6439871cfc0d1f1f5d791071cef [file] [log] [blame]
Victor Stinnerdb39a0d2014-01-16 18:58:01 +01001.. currentmodule:: asyncio
2
Victor Stinner0f3e6bc2014-02-19 23:15:02 +01003.. _asyncio-dev:
4
Victor Stinnerdb39a0d2014-01-16 18:58:01 +01005Develop with asyncio
6====================
7
8Asynchronous programming is different than classical "sequential" programming.
Eli Bendersky679688e2014-01-20 08:13:31 -08009This page lists common traps and explains how to avoid them.
Victor Stinnerdb39a0d2014-01-16 18:58:01 +010010
11
Victor Stinner62511fd2014-06-23 00:36:11 +020012.. _asyncio-debug-mode:
13
14Debug mode of asyncio
15---------------------
16
17To enable the debug mode globally, set the environment variable
Victor Stinnerd71dcbb2014-08-25 17:04:12 +020018:envvar:`PYTHONASYNCIODEBUG` to ``1``. To see debug traces, set the log level
19of the :ref:`asyncio logger <asyncio-logger>` to :py:data:`logging.DEBUG`. The
20simplest configuration is::
21
22 import logging
23 # ...
24 logging.basicConfig(level=logging.DEBUG)
25
26Examples of effects of the debug mode:
Victor Stinner62511fd2014-06-23 00:36:11 +020027
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 Stinner606ab032014-02-01 03:18:58 +010043.. _asyncio-multithreading:
44
45Concurrency and multithreading
46------------------------------
47
48An event loop runs in a thread and executes all callbacks and tasks in the same
Victor Stinner86516d92014-02-18 09:22:00 +010049thread. While a task is running in the event loop, no other task is running in
Victor Stinner5cb84ed2014-02-04 18:18:27 +010050the same thread. But when the task uses ``yield from``, the task is suspended
51and the event loop executes the next task.
Victor Stinner606ab032014-02-01 03:18:58 +010052
Victor Stinner5cb84ed2014-02-04 18:18:27 +010053To schedule a callback from a different thread, the
54:meth:`BaseEventLoop.call_soon_threadsafe` method should be used. Example to
Guido van Rossum3c9bb692014-02-04 13:49:34 -080055schedule a coroutine from a different thread::
Victor Stinner5cb84ed2014-02-04 18:18:27 +010056
57 loop.call_soon_threadsafe(asyncio.async, coro_func())
Victor Stinner606ab032014-02-01 03:18:58 +010058
Victor Stinner790202d2014-02-07 19:03:05 +010059Most asyncio objects are not thread safe. You should only worry if you access
60objects outside the event loop. For example, to cancel a future, don't call
61directly its :meth:`Future.cancel` method, but::
62
63 loop.call_soon_threadsafe(fut.cancel)
64
Victor Stinner606ab032014-02-01 03:18:58 +010065To handle signals and to execute subprocesses, the event loop must be run in
66the main thread.
67
68The :meth:`BaseEventLoop.run_in_executor` method can be used with a thread pool
69executor to execute a callback in different thread to not block the thread of
70the event loop.
71
72.. seealso::
73
74 See the :ref:`Synchronization primitives <asyncio-sync>` section to
75 synchronize tasks.
76
77
Victor Stinner45b27ed2014-02-01 02:36:43 +010078.. _asyncio-handle-blocking:
79
Eli Benderskyb73c8332014-02-09 06:07:47 -080080Handle blocking functions correctly
Victor Stinnerdb39a0d2014-01-16 18:58:01 +010081-----------------------------------
82
83Blocking functions should not be called directly. For example, if a function
84blocks for 1 second, other tasks are delayed by 1 second which can have an
85important impact on reactivity.
86
87For networking and subprocesses, the :mod:`asyncio` module provides high-level
Victor Stinner9592edb2014-02-02 15:03:02 +010088APIs like :ref:`protocols <asyncio-protocol>`.
Victor Stinnerdb39a0d2014-01-16 18:58:01 +010089
90An executor can be used to run a task in a different thread or even in a
91different process, to not block the thread of the event loop. See the
Victor Stinner606ab032014-02-01 03:18:58 +010092:meth:`BaseEventLoop.run_in_executor` method.
Victor Stinnerdb39a0d2014-01-16 18:58:01 +010093
Victor Stinner45b27ed2014-02-01 02:36:43 +010094.. seealso::
95
96 The :ref:`Delayed calls <asyncio-delayed-calls>` section details how the
97 event loop handles time.
98
Victor Stinnerdb39a0d2014-01-16 18:58:01 +010099
100.. _asyncio-logger:
101
Victor Stinner45b27ed2014-02-01 02:36:43 +0100102Logging
103-------
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100104
Victor Stinner45b27ed2014-02-01 02:36:43 +0100105The :mod:`asyncio` module logs information with the :mod:`logging` module in
106the logger ``'asyncio'``.
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100107
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100108
109.. _asyncio-coroutine-not-scheduled:
110
111Detect coroutine objects never scheduled
112----------------------------------------
113
Victor Stinner530ef2f2014-07-08 12:39:10 +0200114When 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
116of 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
118warning <asyncio-logger>` to detect it.
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100119
120Example with the bug::
121
122 import asyncio
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100123
124 @asyncio.coroutine
125 def test():
126 print("never scheduled")
127
128 test()
129
130Output in debug mode::
131
Victor Stinner530ef2f2014-07-08 12:39:10 +0200132 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 Stinnerdb39a0d2014-01-16 18:58:01 +0100136
Victor Stinner530ef2f2014-07-08 12:39:10 +0200137The 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 Stinnerdb39a0d2014-01-16 18:58:01 +0100143
144
Victor Stinner530ef2f2014-07-08 12:39:10 +0200145Detect exceptions never consumed
146--------------------------------
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100147
148Python usually calls :func:`sys.displayhook` on unhandled exceptions. If
Victor Stinner530ef2f2014-07-08 12:39:10 +0200149: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
152traceback where the exception was raised.
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100153
154Example 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
166Output::
167
Victor Stinner530ef2f2014-07-08 12:39:10 +0200168 Task exception was never retrieved
Victor Stinnerab1c8532014-10-12 21:37:16 +0200169 future: <Task finished coro=<coro() done, defined at asyncio/coroutines.py:139> exception=Exception('not consumed',)>
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100170 Traceback (most recent call last):
Victor Stinnerab1c8532014-10-12 21:37:16 +0200171 File "asyncio/tasks.py", line 237, in _step
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100172 result = next(coro)
Victor Stinner530ef2f2014-07-08 12:39:10 +0200173 File "asyncio/coroutines.py", line 141, in coro
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100174 res = func(*args, **kw)
Victor Stinnerab1c8532014-10-12 21:37:16 +0200175 File "test.py", line 5, in bug
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100176 raise Exception("not consumed")
177 Exception: not consumed
178
Victor Stinner530ef2f2014-07-08 12:39:10 +0200179:ref:`Enable the debug mode of asyncio <asyncio-debug-mode>` to get the
Victor Stinnerab1c8532014-10-12 21:37:16 +0200180traceback 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 Stinner530ef2f2014-07-08 12:39:10 +0200197
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100198There are different options to fix this issue. The first option is to chain to
199coroutine 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
212Another option is to use the :meth:`BaseEventLoop.run_until_complete`
213function::
214
215 task = asyncio.async(bug())
216 try:
217 loop.run_until_complete(task)
218 except Exception:
219 print("exception consumed")
220
221See also the :meth:`Future.exception` method.
222
223
Victor Stinner530ef2f2014-07-08 12:39:10 +0200224Chain correctly coroutines
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100225--------------------------
226
227When a coroutine function calls other coroutine functions and tasks, they
Eli Bendersky679688e2014-01-20 08:13:31 -0800228should be chained explicitly with ``yield from``. Otherwise, the execution is
229not guaranteed to be sequential.
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100230
Eli Bendersky679688e2014-01-20 08:13:31 -0800231Example with different bugs using :func:`asyncio.sleep` to simulate slow
232operations::
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100233
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 Stinnerf40c6632014-01-28 23:32:40 +0100262 loop.close()
Victor Stinnerdb39a0d2014-01-16 18:58:01 +0100263
264Expected output::
265
266 (1) create file
267 (2) write into file
268 (3) close file
269 Pending tasks at exit: set()
270
271Actual output::
272
273 (3) close file
274 (2) write into file
Victor Stinner530ef2f2014-07-08 12:39:10 +0200275 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 Stinnerdb39a0d2014-01-16 18:58:01 +0100278
279The loop stopped before the ``create()`` finished, ``close()`` has been called
280before ``write()``, whereas coroutine functions were called in this order:
281``create()``, ``write()``, ``close()``.
282
283To 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
293Or 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 Stinner530ef2f2014-07-08 12:39:10 +0200303
304.. _asyncio-pending-task-destroyed:
305
306Pending task destroyed
307----------------------
308
309If 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
312Example of log::
313
314 Task was destroyed but it is pending!
Victor Stinnerab1c8532014-10-12 21:37:16 +0200315 task: <Task pending coro=<kill_me() done, defined at test.py:5> wait_for=<Future pending cb=[Task._wakeup()]>>
Victor Stinner530ef2f2014-07-08 12:39:10 +0200316
317:ref:`Enable the debug mode of asyncio <asyncio-debug-mode>` to get the
Victor Stinnerab1c8532014-10-12 21:37:16 +0200318traceback 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 Stinner530ef2f2014-07-08 12:39:10 +0200326
327.. seealso::
328
329 :ref:`Detect coroutine objects never scheduled <asyncio-coroutine-not-scheduled>`.
330