Stop including location exception was caught in Failure

[itamarst]

About 2/3rds of the time spent in creating Failure objects, and therefore in error handling in Deferred, is constructing Deferred.stack. I would argue this isn't necessary, insofar as Python doesn't include this info, and it's a huge performance hit.

Comparing Python tracebacks to Failure tracebacks

Consider the following script:

from twisted.python.failure import Failure
import sys
import traceback

def f():
    def h():
        1 / 0

    def g():
        h()

    g()

def a():
    try:
        f()
    except:
        if sys.argv[1] == "python":
            print("PYTHON")
            traceback.print_tb(sys.exc_info()[-1], file=sys.stdout)
        else:
            print("TWISTED")
            failure = Failure()
            failure.cleanFailure()
            failure.printTraceback(sys.stdout)

a()

When run:

(py311) itamarst@louverture:~/devel/twisted$ python 12227.py python
PYTHON
  File "/home/itamarst/devel/twisted/12227.py", line 16, in a
    f()
  File "/home/itamarst/devel/twisted/12227.py", line 12, in f
    g()
  File "/home/itamarst/devel/twisted/12227.py", line 10, in g
    h()
  File "/home/itamarst/devel/twisted/12227.py", line 7, in h
    1 / 0
    ~~^~~
(py311) itamarst@louverture:~/devel/twisted$ python 12227.py twisted
TWISTED
Traceback (most recent call last):
  File "/home/itamarst/devel/twisted/12227.py", line 26, in <module>    # <---- only Twisted has this bit!
    a()
--- <exception caught here> ---
  File "/home/itamarst/devel/twisted/12227.py", line 16, in a
    f()
  File "/home/itamarst/devel/twisted/12227.py", line 12, in f
    g()
  File "/home/itamarst/devel/twisted/12227.py", line 10, in g
    h()
  File "/home/itamarst/devel/twisted/12227.py", line 7, in h
    1 / 0
builtins.ZeroDivisionError: division by zero

Notice that Twisted includes where the Failure was created, whereas Python only includes the traceback.

Why omit this? Performance

Two thirds of the time spent in Deferred error handling of Failure (as measured by the relevant benchmark) is tied in creating Deferred.stack.

A compromise

If we want to be extra nice, this extra info can be turned on when Deferred.debug is turned on.

A counterargument

It may be that the info of "where did we catch the exception" is super-helpful. I am not sure I have enough relevant experience in debugging production Twisted applications to have a good opinion.

[glyph]

At the time that this code was written, the stack was only present during catching of the exception, and we had to capture it at that moment or it would be lost.

Today, the stack is already preserved on the exception itself, as __traceback__.

Could we turn Failure.stack into a facade over BaseException.__traceback__, and realize it only if it is used?

This is not necessarily a fully compatible change, but it's certainly more compatible than just dropping the information, and the only place it would be a problem is if the user is mutably re-raising the same exception, and that just isn't a practical concern most of the time in non-Twisted code, so I doubt it would be a problem for us either.

[itamarst]

Probably could do that, yeah. Keep in mind though that Failure.cleanFailure() is called by Deferred in common code paths (not sure why!) and that would remove the __traceback__, which would force creation of Failure.stack, which means in practice most of the performance benefit would be lost if we auto-populate Failure.stack.

That being said, the most expensive thing is f.f_lineno, so if we have a traceback at least that part might be faster. So that's another alternative. It'd likely still be a a bunch slower than this PR though.

[itamarst]

To make maybe this clearer, options are:

• Make Failure.stack populated only if accessed, which means we need to change Failure.cleanFailure() to not wipe __traceback__.
• Make Failure.stack populate from the exception __traceback__, which is likely faster.
• This PR.
• Something else.

[glyph]

Wait, what is __exception__?

[glyph]

Keep in mind though that Failure.cleanFailure() is called by Deferred in common code paths (not sure why!)

The purpose is to avoid creating expensive or uncollectable cycles. Perhaps we could tone that down if __traceback__ already has some mechanism for dealing with that? It must, right?

[itamarst]

I mean __traceback__.

[glyph]

I mean __traceback__.

Gotcha. I was just a little thrown because you used both, and I thought you were trying to draw a distinction:)

[itamarst]

Update: Wrote some stuff here that was wrong, deleting (didn't realize the traceback's tb_frame is what includes the frame that Failure.stack uses.).

[itamarst]

After further research, going over the alternatives, only things I can come up with are:

• Make Failure.stack populated only if accessed, which means we need to change Failure.cleanFailure() to not wipe __traceback__.
• Strategy in the PR.

Not viable:

• Make Failure.stack populate from the exception __traceback__. This won't be faster, it's the exact same mechanism currently used.

So the question is, can we not wipe __traceback__. And... cleanFailure() was added to Twisted in 2002 (complete with Pokey the Penguin reference): 40ffee8

In 2002 Python didn't have garbage collection, so circular references would lead to memory leaks. These days, Python does have support for cleaning up circular references. I would therefore suggest that cleanFailure is unnecessary in most cases. You will hold on to memory for too long only if the Deferred just sits there with no error handling and is never cleaned up some other way.

[itamarst]

Making cleanFailure() no longer called by Deferred would also allow making Deferred.frames be lazy and only constructed on demand, which would speed things up even more.

[itamarst]

I created #12234 as an alternative proposal to this issue.

[glyph]

It's possible you misunderstood what Failure.stack is?

In fairness to your various corrections here I think I might also be a little confused about the purpose of these different variables :)

[glyph]

How much time / work is _safeReprVars? To be honest I'm a little shocked that in this discussion that is not coming up as a gigantic hilarious waste of resources.

[itamarst]

I already fixed _safeReprVars in a different PR, #12231.

[itamarst]

After some thought and discussion in #12234, I would like to reiterate the desire in this issue not to include the "where the exception was caught" in the output. Or, to put it another way, the stack trace above where the try/except caught the exception.

So far I haven't had any response indicating this information is useful. Maybe it is! But if it isn't, it's a lot of work for no reason.

To reiterate the question: Twisted's error output has a traceback going all the way from the top of the stack down to the bottom. Python only reports part of that info, from inside the try/except to the bottom. Is there a reason we can't just stick to what Python does?

[glyph]

To reiterate the question: Twisted's error output has a traceback going all the way from the top of the stack down to the bottom. Python only reports part of that info, from inside the try/except to the bottom. Is there a reason we can't just stick to what Python does?

OK, let me address my own view on this specific question: I am happy to just do what Python does.

I think that including this additional information is another historical relic, attempting to give developers something to work from when dealing with inscrutable tracebacks that appeared to originate from nowhere due to the relative lack of information that Deferreds had to work with.

Nowadays async/await Deferred call stacks are perfectly legible, and this concern is less and less relevant as more sequential code adopts that pattern, which is more efficient than long callback chains anyway. Additionally it's not clear that this information was ever very useful, just an oblique additional clue in confusing circumstances.

[glyph]

(Not to mention the fact that, as you have already mentioned, Python's native tracebacks look much nicer these days anyway, and we have missed several generations of substantial improvements.)

[twm]

FWIW, when I was new to Twisted I had to learn how to read Twisted tracebacks by skipping to the <exception caught here> bit. I've generally viewed the stuff before that marker as noise.

[glyph]

FWIW, when I was new to Twisted I had to learn how to read Twisted tracebacks by skipping to the <exception caught here> bit. I've generally viewed the stuff before that marker as noise.

OK, let's get rid of it.