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

pitrou · 2017-11-07T13:21:45Z

https://bugs.python.org/issue31970

1st1 · 2017-11-07T13:37:09Z

~~So how much faster the new code is?~~

Never mind, I saw the explanation in the issue.

1st1 · 2017-11-07T13:39:39Z

Lib/asyncio/events.py

+        # This is heuristically the max number of entries we're gonna pop + 1
+        # (we're only interested in displaying the top of stack)
+        # If this is too small, tests will fail.
+        limit = 4


Can we bump this to 10? It's a debug mode after all, and seeing only 2-3 lines in traceback is sometimes not enough.

The traceback is never displayed. It's only used for Future.__repr__, which prints the line at which the future was created (i.e. the top-of-stack).

IIRC Task.__del__ and CoroWrapper pass it to the loop's logger to print some debug info. In which case the full traceback would be printed to the user, no?

Oh, yes, you're right. I agree with bumping to 10 then.

Can you add it as a constant to asyncio/constants.py? Also, we need to update loop.default_exception_handler() method to say that we only display 10 topmost frames.

1st1

I'd only bump 4 to 10.

pitrou · 2017-11-07T13:44:01Z

So how much faster the new code is?

Depends on your usage :-) With a small stack it is 2x faster. With a 50-deep stack it is 10x faster.
(note I'm testing with a debug Python, but the effect should be similar on a release one)

Here is a snippet:
https://gist.github.com/pitrou/296447d747f043cc62fd91a6c114983e
You can time it using ./python -m timeit -s "from aiodebugperf import func" "func()".
(you can also cProfile it to see where time is spent)

asvetlov · 2017-11-07T14:08:25Z

+1 for 10. Or maybe at least 7.
I feel that 4 is too small value.

1st1

Can you add it as a constant to asyncio/constants.py? Also, we need to update loop.default_exception_handler() method to say that we only display 10 topmost frames.

bedevere-bot · 2017-11-07T14:48:39Z

A Python core developer has requested some changes be made to your pull request before we can consider merging it. If you could please address their requests along with any other requests in other reviews from core developers that would be appreciated.

Once you have made the requested changes, please leave a comment on this pull request containing the phrase I have made the requested changes; please review again. I will then notify any core developers who have left a review that you're ready for them to take another look at this pull request.

1st1 · 2017-11-07T14:51:21Z

@Mariatta I think I just saw a tiny bug in bedevere-bot:

core-dev A requests changes; bedevere-bot assigns an awaiting changes label.
core-dev B approves the PR; bedevere-bot removes the awaiting changes label.

The label should only be removed when all reviewers clear the PR.

pitrou · 2017-11-07T14:53:00Z

@1st1 are you ok with backporting to 3.6 as well?

1st1 · 2017-11-07T14:54:00Z

@1st1 are you ok with backporting to 3.6 as well?

Yeah, I think it's fine.

1st1 · 2017-11-07T15:03:09Z

Lib/test/test_asyncio/test_tasks.py

        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, maybe truncated\):\n'


Can we replace "maybe truncated" to "truncated to {} last lines"?

"truncated to {DEBUG_STACK_DEPTH} frames" if I understood correctly

vstinner

If I understand correctly, getting the previous behaviour is as simple as "asyncio.constants.DEBUG_STACK_DEPTH = None". Right?

Maybe mention this constant in Doc/library/asyncio-dev.rst to explain how to not get truncated tracebacks.

vstinner · 2017-11-07T15:09:15Z

Lib/test/test_asyncio/test_tasks.py

        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, maybe truncated\):\n'


"truncated to {DEBUG_STACK_DEPTH} frames" if I understood correctly

vstinner · 2017-11-07T15:10:28Z

Lib/asyncio/constants.py

+
+# 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)


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".

vstinner · 2017-11-07T15:13:43Z

If you document the constant, I'm ok to merge this change.

pitrou · 2017-11-07T15:24:00Z

I'm not sure the constant should be documented. Other constants are not. They don't seem meant to be changed by users.

1st1 · 2017-11-07T15:28:22Z

If you document the constant, I'm ok to merge this change.

I don't think we need to document every constant we have any asyncio. Those who debug super problematic cases can always go and look at the implementation and bump the number to 10000 themselves. For an average asyncio user all these little details about debug mode and its constants in the documentation is just noise.

vstinner · 2017-11-07T15:30:52Z

I'm not sure the constant should be documented. Other constants are not. They don't seem meant to be changed by users.

I'm not proposing to document all constants. I asked you to document the constant since you change the behaviour of the debug mode of asyncio. It can be surprising to upgrade Python and suddenly tracebacks are truncated: how are you supposed to deal with this? Dig into asyncio source code to understand?

pitrou · 2017-11-07T15:32:06Z

It can be surprising to upgrade Python and suddenly tracebacks are truncated: how are you supposed to deal with this?

Read the error message? It clearly says the traceback is truncated :-)
Do you mean it's sometimes necessary to have the full traceback?

asvetlov · 2017-11-07T15:36:52Z

-1 for constant documenting

vstinner · 2017-11-07T15:37:49Z

Do you mean it's sometimes necessary to have the full traceback?

I think so. Try maybe yourself by truncating to 1 frame: are you always able to find the bug? :-)

Anyway, in case of doubt, I prefer to document the option.

Note: I'm planning to make faulthandler configurable to allow to display more than 100 frames, 100 threads and strings longer than 500 characters... But nobody complained. Maybe 100 frames is enough for everyone, or people who hit such limitations are able to modify CPython and recompile it :-)

Well, 100 frames is much higher than 10 frames :-)

I was going to say that my tracemalloc module was also limited to 100 frames, but I see that I removed this limitation to use a dynamically allocated array :-)

vstinner · 2017-11-07T15:48:44Z

If @1st1 and @asvetlov are against documenting the constant, ignore my request ;-)

pitrou · 2017-11-07T15:52:54Z

Thank you @Haypo :-)

miss-islington · 2017-11-07T16:23:31Z

Thanks @pitrou for the PR 🌮🎉.. I'm working now to backport this PR to: 3.6.
🐍🍒⛏🤖

miss-islington · 2017-11-07T16:24:34Z

Sorry, @pitrou, I could not cleanly backport this to 3.6 due to a conflict.
Please backport using cherry_picker on command line.
cherry_picker 921e9432a1461bbf312c9c6dcc2b916be6c05fa0 3.6

bedevere-bot · 2017-11-07T16:27:21Z

GH-4322 is a backport of this pull request to the 3.6 branch.

…ythonGH-4314) * bpo-31970: Reduce performance overhead of asyncio debug mode.. (cherry picked from commit 921e943)

…H-4314) (#4322) * bpo-31970: Reduce performance overhead of asyncio debug mode.. (cherry picked from commit 921e943)

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

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

1b39738

pitrou requested a review from 1st1 as a code owner November 7, 2017 13:21

the-knights-who-say-ni added the CLA signed label Nov 7, 2017

bedevere-bot added the awaiting merge label Nov 7, 2017

1st1 reviewed Nov 7, 2017

View reviewed changes

1st1 approved these changes Nov 7, 2017

View reviewed changes

Increase stack limit and mention truncation in debug stack dump

aa6a0cf

1st1 requested changes Nov 7, 2017

View reviewed changes

bedevere-bot added awaiting changes and removed awaiting merge labels Nov 7, 2017

asvetlov approved these changes Nov 7, 2017

View reviewed changes

bedevere-bot added awaiting merge and removed awaiting changes labels Nov 7, 2017

1st1 added the needs backport to 3.6 label Nov 7, 2017

Improve docstring and use a named constant

ab46acf

1st1 reviewed Nov 7, 2017

View reviewed changes

vstinner reviewed Nov 7, 2017

View reviewed changes

Display truncation depth in error message

2b05aab

1st1 approved these changes Nov 7, 2017

View reviewed changes

pitrou merged commit 921e943 into python:master Nov 7, 2017

bedevere-bot removed the awaiting merge label Nov 7, 2017

pitrou deleted the aio_debug_perf branch November 7, 2017 16:23

bedevere-bot removed the needs backport to 3.6 label Nov 7, 2017

pitrou added a commit to pitrou/cpython that referenced this pull request Nov 7, 2017

[3.6] bpo-31970: Reduce performance overhead of asyncio debug mode. (p…

066ba5c

…ythonGH-4314) * bpo-31970: Reduce performance overhead of asyncio debug mode.. (cherry picked from commit 921e943)

pitrou added a commit that referenced this pull request Nov 7, 2017

[3.6] bpo-31970: Reduce performance overhead of asyncio debug mode. (G…

d8d218f

…H-4314) (#4322) * bpo-31970: Reduce performance overhead of asyncio debug mode.. (cherry picked from commit 921e943)

Mariatta mentioned this pull request Nov 7, 2017

Only remove "awaiting change" PR label after all reviewers approved. python/bedevere#71

Closed

embray pushed a commit to embray/cpython that referenced this pull request Nov 9, 2017

bpo-31970: Reduce performance overhead of asyncio debug mode. (python…

b29be26

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

Uh oh!

Conversation

pitrou commented Nov 7, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

1st1 commented Nov 7, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

1st1 left a comment

Choose a reason for hiding this comment

Uh oh!

pitrou commented Nov 7, 2017

Uh oh!

asvetlov commented Nov 7, 2017

Uh oh!

1st1 left a comment

Choose a reason for hiding this comment

Uh oh!

bedevere-bot commented Nov 7, 2017

Uh oh!

1st1 commented Nov 7, 2017

Uh oh!

pitrou commented Nov 7, 2017

Uh oh!

1st1 commented Nov 7, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

vstinner left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

vstinner commented Nov 7, 2017

Uh oh!

pitrou commented Nov 7, 2017

Uh oh!

1st1 commented Nov 7, 2017

Uh oh!

vstinner commented Nov 7, 2017

Uh oh!

pitrou commented Nov 7, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

asvetlov commented Nov 7, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

vstinner commented Nov 7, 2017

Uh oh!

vstinner commented Nov 7, 2017

Uh oh!

pitrou commented Nov 7, 2017

Uh oh!

miss-islington commented Nov 7, 2017

Uh oh!

miss-islington commented Nov 7, 2017

Uh oh!

bedevere-bot commented Nov 7, 2017

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

pitrou commented Nov 7, 2017 •

edited

Loading

1st1 commented Nov 7, 2017 •

edited

Loading

pitrou commented Nov 7, 2017 •

edited

Loading

asvetlov commented Nov 7, 2017 •

edited

Loading