PEP 830: Add timestamps to exceptions and tracebacks

This PEP adds an optional timestamp to all exceptions that records when the exception was instantiated with no observable overhead. When enabled via environment variable or command-line flag, formatted tracebacks display this timestamp alongside the exception message.

If you’ve ever debugged a production Python system involving many forms of concurrency and wished you had more information about what happened when, this PEP may be for you. The point at which an exception is logged or rendered with a logging system supplied timestamp is often not the same as the time it happened.

If you never debug complex applications like that, you won’t even notice that this feature exists. It is off by default, to be enabled only by those in environments who feel the above pain. Win win.

5 Likes

I think the time it was raised may be more interesting than the time it was instantiated.

2 Likes

Can this not already be done with something like:

def excepthook(exctype, value, traceback):
    value.add_note(f"Raised at {datetime.now()}")
    sys.__excepthook__(exctype, value, traceback)

sys.excepthook = excepthook

(P.S. It would help if the example in the PEP was self contained so I could try it.)

That would be a more intrusive change, though, as the interpreter loop would need to store the info somewhere else until the exception was instantiated when a stateless exception is raised by type.

User code can also force the two times to match by instantiating when raising (which is necessarily the case for stateful exceptions).

I think it can attach the timestamp in do_raise (see here) just after the raised type is instantiated.

I was thinking about cases where the exception is created before the raise. Maybe it’s returned from some function, cached, and raised somewhere else at a later time. It’s also possible to raise the same exception instance more than once. And of course we would need to defined whether the timestamp is overwritten in a reraise (a naked raise or an explicit `raise e’). Setting the timestamp at object creation time bypasses these question because the object is only created once. But I’m questioning why that is the most semantically meaningful timestamp to use here.

1 Like

How often does code actually have a distinction between time of instantiation and time of raise in practice?

I understand it is possible to do a bare raise SomeExceptionType without an immediately constructing (”message”) argument I believe causes this. But that one doesn’t matter, do_raise immediately calls it to do the instantiation. Nevermind that bare raises without () don’t feel like a normal idiom I’ve seen in code since basically forever. Even in the C API, the PyErr_Set* APIs do the same thing from what I can tell by calling _PyErr_CreateException. It seems like most everything normalizes the exception into an instance pretty quickly.

Does anyone have practical in-use examples of code creating an exception instance well before the raise, or even the unsatisfiable pattern of (eek!) re-using a pre-created exception instance across many disconnected raises? I believe we do this internally for some last-ditch MemoryError situations, but that’s a special case that seems fine to ignore. It is certainly possible for people to write code in Python or C that does it. But why would anyone?

PEP-830 update TODO: We should probably explicitly zero out any singleton exception instance timestamps we have in our own internals.

Regardless, while pondering that I’m going to go brush up on the ceval.h::do_raise path to better understand possibilities.

This is also one of those areas where trying to be perfect could be not worthwhile. I expect instantiation time will cover the bulk of use cases. If we find otherwise through experience we could change how the time collection is done.

What are the consequences on internal-use exceptions like StopIteration? Querying the time of day takes a notable amount of time:

rosuav@sikorsky:~$ python3 -m timeit -s 'from time import time' 'time()'
10000000 loops, best of 5: 24 nsec per loop
rosuav@sikorsky:~$ python3 -m timeit -s 'from time import time' 'for _ in (): pass'
50000000 loops, best of 5: 5.87 nsec per loop
rosuav@sikorsky:~$ python3 -m timeit -s 'def time(): pass' 'time()'
20000000 loops, best of 5: 11.7 nsec per loop

and I’d hope that this can be avoided in these situations.

did you read the PEP? (ie: StopIteration and StopAsyncIteration needs are answered in there already, yes this was worth considering and is a special case!)

Regarding ceval’s do_raise - that probably isn’t the touchpoint to do it if we wanted time of raise rather than instantiation as it is eval loop focused.

But I think Python/errors.c::_PyErr_SetRaisedException might be. Assuming everything goes through that rather than diddling with tstate->current_exception directly (which feels like a hard assumption to make, though it appears true by my ripgrepping).

I have written code which ‘asserts’ a bunch of things by instantiating a exceptions throughout a function, adding them to a list and then raising them as an ExceptionGroup at the end. This removes the extra step of raising the exception each time, catching it, only to add it to an exception group. I’m not sure if this is best practice or anything, but it’s a pattern that works for me.

So if the timestamp is added at raise-time, I think this PEP would no longer cover such exceptions as they are never actually raised. I’m not sure if this is a good or a bad thing, just something to consider.

Doh. I did skim it, and I was thinking initially about some others like AttributeError, but then when I went to make the point about the time cost, I switched to StopIteration because it’s easier to demonstrate. So, yes, that particular one IS handled (yay!). What I should have asked is: will things like hasattr calls become slower because of internal time queries?

rosuav@sikorsky:~$ python3 -m timeit -s 'from time import time' 'time()'
10000000 loops, best of 5: 23.8 nsec per loop
rosuav@sikorsky:~$ python3 -m timeit 'hasattr(None, "test")'
20000000 loops, best of 5: 14.4 nsec per loop

Same applies (I think??) to dict.setdefault and __missing__. And maybe I should have stuck with my original thought, since that would have shown me that the time cost isn’t nearly as distinct.