Skip to content

bpo-31970: Reduce performance overhead of asyncio debug mode. #4314

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 4 commits into from
Nov 7, 2017
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions Lib/asyncio/base_events.py
Original file line number Diff line number Diff line change
Expand Up @@ -1223,6 +1223,11 @@ def default_exception_handler(self, context):
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()`.
"""
Expand Down
5 changes: 5 additions & 0 deletions Lib/asyncio/constants.py
Original file line number Diff line number Diff line change
Expand Up @@ -5,3 +5,8 @@

# 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)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You may document that this value is passed to the limit parameter of traceback.extract_stack(), or maybe just document that None means "no limit".

DEBUG_STACK_DEPTH = 10
8 changes: 5 additions & 3 deletions Lib/asyncio/coroutines.py
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@
import types

from . import compat
from . import constants
from . import events
from . import base_futures
from .log import logger
Expand Down Expand Up @@ -91,7 +92,7 @@ def __init__(self, gen, func=None):
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)

Expand Down Expand Up @@ -183,8 +184,9 @@ def __del__(self):
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)

Expand Down
21 changes: 20 additions & 1 deletion Lib/asyncio/events.py
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,8 @@
import threading
import traceback

from . import constants


def _get_function_source(func):
func = inspect.unwrap(func)
Expand Down Expand Up @@ -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."""

Expand All @@ -85,7 +104,7 @@ def __init__(self, callback, args, loop):
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

Expand Down
2 changes: 1 addition & 1 deletion Lib/asyncio/futures.py
Original file line number Diff line number Diff line change
Expand Up @@ -77,7 +77,7 @@ def __init__(self, *, loop=None):
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

Expand Down
2 changes: 1 addition & 1 deletion Lib/test/test_asyncio/test_tasks.py
Original file line number Diff line number Diff line change
Expand Up @@ -1981,7 +1981,7 @@ def coro_noop():

regex = (r'^<CoroWrapper %s\(?\)? .* at %s:%s, .*> '
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\(\)$'
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Reduce performance overhead of asyncio debug mode.