From 921e9432a1461bbf312c9c6dcc2b916be6c05fa0 Mon Sep 17 00:00:00 2001 From: Antoine Pitrou Date: Tue, 7 Nov 2017 17:23:29 +0100 Subject: bpo-31970: Reduce performance overhead of asyncio debug mode. (#4314) * bpo-31970: Reduce performance overhead of asyncio debug mode. --- Lib/asyncio/base_events.py | 5 +++++ Lib/asyncio/constants.py | 5 +++++ Lib/asyncio/coroutines.py | 8 +++++--- Lib/asyncio/events.py | 21 ++++++++++++++++++++- Lib/asyncio/futures.py | 2 +- Lib/test/test_asyncio/test_tasks.py | 2 +- .../2017-11-07-14-20-09.bpo-31970.x4EN_9.rst | 1 + 7 files changed, 38 insertions(+), 6 deletions(-) create mode 100644 Misc/NEWS.d/next/Library/2017-11-07-14-20-09.bpo-31970.x4EN_9.rst diff --git a/Lib/asyncio/base_events.py b/Lib/asyncio/base_events.py index 2a5a4f9..b94856c 100644 --- a/Lib/asyncio/base_events.py +++ b/Lib/asyncio/base_events.py @@ -1223,6 +1223,11 @@ class BaseEventLoop(events.AbstractEventLoop): handler is set, and can be called by a custom exception handler that wants to defer to the default behavior. + This default handler logs the error message and other + context-dependent information. In debug mode, a truncated + stack trace is also appended showing where the given object + (e.g. a handle or future or task) was created, if any. + The context parameter has the same meaning as in `call_exception_handler()`. """ diff --git a/Lib/asyncio/constants.py b/Lib/asyncio/constants.py index f9e1232..e74209e 100644 --- a/Lib/asyncio/constants.py +++ b/Lib/asyncio/constants.py @@ -5,3 +5,8 @@ LOG_THRESHOLD_FOR_CONNLOST_WRITES = 5 # Seconds to wait before retrying accept(). ACCEPT_RETRY_DELAY = 1 + +# Number of stack entries to capture in debug mode. +# The large the number, the slower the operation in debug mode +# (see extract_stack() in events.py) +DEBUG_STACK_DEPTH = 10 diff --git a/Lib/asyncio/coroutines.py b/Lib/asyncio/coroutines.py index b2adaad..520a309 100644 --- a/Lib/asyncio/coroutines.py +++ b/Lib/asyncio/coroutines.py @@ -10,6 +10,7 @@ import traceback import types from . import compat +from . import constants from . import events from . import base_futures from .log import logger @@ -91,7 +92,7 @@ class CoroWrapper: assert inspect.isgenerator(gen) or inspect.iscoroutine(gen), gen self.gen = gen self.func = func # Used to unwrap @coroutine decorator - self._source_traceback = traceback.extract_stack(sys._getframe(1)) + self._source_traceback = events.extract_stack(sys._getframe(1)) self.__name__ = getattr(gen, '__name__', None) self.__qualname__ = getattr(gen, '__qualname__', None) @@ -183,8 +184,9 @@ class CoroWrapper: tb = getattr(self, '_source_traceback', ()) if tb: tb = ''.join(traceback.format_list(tb)) - msg += ('\nCoroutine object created at ' - '(most recent call last):\n') + msg += (f'\nCoroutine object created at ' + f'(most recent call last, truncated to ' + f'{constants.DEBUG_STACK_DEPTH} last lines):\n') msg += tb.rstrip() logger.error(msg) diff --git a/Lib/asyncio/events.py b/Lib/asyncio/events.py index 270a5e4..f2f2e28 100644 --- a/Lib/asyncio/events.py +++ b/Lib/asyncio/events.py @@ -19,6 +19,8 @@ import sys import threading import traceback +from . import constants + def _get_function_source(func): func = inspect.unwrap(func) @@ -72,6 +74,23 @@ def _format_callback_source(func, args): return func_repr +def extract_stack(f=None, limit=None): + """Replacement for traceback.extract_stack() that only does the + necessary work for asyncio debug mode. + """ + if f is None: + f = sys._getframe().f_back + if limit is None: + # Limit the amount of work to a reasonable amount, as extract_stack() + # can be called for each coroutine and future in debug mode. + limit = constants.DEBUG_STACK_DEPTH + stack = traceback.StackSummary.extract(traceback.walk_stack(f), + limit=limit, + lookup_lines=False) + stack.reverse() + return stack + + class Handle: """Object returned by callback registration methods.""" @@ -85,7 +104,7 @@ class Handle: self._cancelled = False self._repr = None if self._loop.get_debug(): - self._source_traceback = traceback.extract_stack(sys._getframe(1)) + self._source_traceback = extract_stack(sys._getframe(1)) else: self._source_traceback = None diff --git a/Lib/asyncio/futures.py b/Lib/asyncio/futures.py index 3dc9c500..472f2a8 100644 --- a/Lib/asyncio/futures.py +++ b/Lib/asyncio/futures.py @@ -79,7 +79,7 @@ class Future: self._loop = loop self._callbacks = [] if self._loop.get_debug(): - self._source_traceback = traceback.extract_stack(sys._getframe(1)) + self._source_traceback = events.extract_stack(sys._getframe(1)) _repr_info = base_futures._future_repr_info diff --git a/Lib/test/test_asyncio/test_tasks.py b/Lib/test/test_asyncio/test_tasks.py index e23963a..1d77f9f 100644 --- a/Lib/test/test_asyncio/test_tasks.py +++ b/Lib/test/test_asyncio/test_tasks.py @@ -1981,7 +1981,7 @@ class BaseTaskTests: regex = (r'^ ' r'was never yielded from\n' - r'Coroutine object created at \(most recent call last\):\n' + r'Coroutine object created at \(most recent call last, truncated to \d+ last lines\):\n' r'.*\n' r' File "%s", line %s, in test_coroutine_never_yielded\n' r' coro_noop\(\)$' diff --git a/Misc/NEWS.d/next/Library/2017-11-07-14-20-09.bpo-31970.x4EN_9.rst b/Misc/NEWS.d/next/Library/2017-11-07-14-20-09.bpo-31970.x4EN_9.rst new file mode 100644 index 0000000..d0c0fb4 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2017-11-07-14-20-09.bpo-31970.x4EN_9.rst @@ -0,0 +1 @@ +Reduce performance overhead of asyncio debug mode. -- cgit v0.12