Proof of concept: Add timestamps to tracebacks.

This came up at work as a suggestion to make debugging what happened in
big async servers with lots of exception groups and exceptions easier.
Timestamps when emitting exception groups containing tracebacks often
with their own nested causes would allow some semblance of order to be
understood.

This is a demo.  If we want such a feature, we should settle on
semantics in a Discuss thread and write it up as a PEP.  This should be
simpler than exception notes (PEP-678) was.  One thought was just to
store the timestamp as a note; but that'd involve string and list
creation on every exception.

Performance testing needs to be done. This is the kind of thing that is
visually distracting, so not all applications want to _see_ the
timestamps.  A knob to turn that on for those who do seems more useful
rather than making that the default.  But the performance impact of
merely collecting the timestamps is worth knowing.

Author: gpshead

Include/cpython/pyerrors.h

@@ -2,11 +2,14 @@
 #  error "this header file must not be included directly"
 #endif
 
+#include "cpython/pytime.h"  /* for PyTime_t */
+
 /* Error objects */
 
 /* PyException_HEAD defines the initial segment of every exception class. */
 #define PyException_HEAD PyObject_HEAD PyObject *dict;\
-             PyObject *args; PyObject *notes; PyObject *traceback;\
+             PyObject *args; PyObject *notes;\
+             PyTime_t timestamp_ns; PyObject *traceback;\
              PyObject *context; PyObject *cause;\
              char suppress_context;
 

Lib/traceback.py

@@ -179,19 +179,21 @@ def format_exception_only(exc, /, value=_sentinel, *, show_group=False, **kwargs
 
 # -- not official API but folk probably use these two functions.
 
-def _format_final_exc_line(etype, value, *, insert_final_newline=True, colorize=False):
+def _format_final_exc_line(etype, value, *, insert_final_newline=True, colorize=False, timestamp=0):
     valuestr = _safe_string(value, 'exception')
     end_char = "\n" if insert_final_newline else ""
+    ts = f" <@t={timestamp:.6f}>" if timestamp else ""
     if colorize:
+        timestamp = f"{ANSIColors.GREY}{ts}{ANSIColors.RESET}" if timestamp else ""
         if value is None or not valuestr:
-            line = f"{ANSIColors.BOLD_MAGENTA}{etype}{ANSIColors.RESET}{end_char}"
+            line = f"{ANSIColors.BOLD_MAGENTA}{etype}{ANSIColors.RESET}{ts}{end_char}"
         else:
-            line = f"{ANSIColors.BOLD_MAGENTA}{etype}{ANSIColors.RESET}: {ANSIColors.MAGENTA}{valuestr}{ANSIColors.RESET}{end_char}"
+            line = f"{ANSIColors.BOLD_MAGENTA}{etype}{ANSIColors.RESET}: {ANSIColors.MAGENTA}{valuestr}{ANSIColors.RESET}{ts}{end_char}"
     else:
         if value is None or not valuestr:
-            line = f"{etype}{end_char}"
+            line = f"{etype}{ts}{end_char}"
         else:
-            line = f"{etype}: {valuestr}{end_char}"
+            line = f"{etype}: {valuestr}{ts}{end_char}"
     return line
 
 
@@ -1004,6 +1006,8 @@ class TracebackException:
 
     - :attr:`__cause__` A TracebackException of the original *__cause__*.
     - :attr:`__context__` A TracebackException of the original *__context__*.
+    - :attr:`__notes__` A reference to the original *__notes__* list.
+    - :attr:`timestamp` When the original exception was created (seconds).
     - :attr:`exceptions` For exception groups - a list of TracebackException
       instances for the nested *exceptions*.  ``None`` for other exceptions.
     - :attr:`__suppress_context__` The *__suppress_context__* value from the
@@ -1057,6 +1061,8 @@ def __init__(self, exc_type, exc_value, exc_traceback, *, limit=None,
             self.__notes__ = [
                 f'Ignored error getting __notes__: {_safe_string(e, '__notes__', repr)}']
 
+        self.timestamp = exc_value.__timestamp_ns__ / 1_000_000_000
+
         self._is_syntax_error = False
         self._have_exc_type = exc_type is not None
         if exc_type is not None:
@@ -1228,22 +1234,22 @@ def format_exception_only(self, *, show_group=False, _depth=0, **kwargs):
 
         indent = 3 * _depth * ' '
         if not self._have_exc_type:
-            yield indent + _format_final_exc_line(None, self._str, colorize=colorize)
+            yield indent + _format_final_exc_line(None, self._str, colorize=colorize, timestamp=self.timestamp)
             return
 
         stype = self.exc_type_str
         if not self._is_syntax_error:
             if _depth > 0:
                 # Nested exceptions needs correct handling of multiline messages.
                 formatted = _format_final_exc_line(
-                    stype, self._str, insert_final_newline=False, colorize=colorize
+                    stype, self._str, insert_final_newline=False, colorize=colorize, timestamp=self.timestamp
                 ).split('\n')
                 yield from [
                     indent + l + '\n'
                     for l in formatted
                 ]
             else:
-                yield _format_final_exc_line(stype, self._str, colorize=colorize)
+                yield _format_final_exc_line(stype, self._str, colorize=colorize, timestamp=self.timestamp)
         else:
             yield from [indent + l for l in self._format_syntax_error(stype, colorize=colorize)]
 

Objects/exceptions.c

@@ -59,6 +59,7 @@ BaseException_new(PyTypeObject *type, PyObject *args, PyObject *kwds)
     /* the dict is created on the fly in PyObject_GenericSetAttr */
     self->dict = NULL;
     self->notes = NULL;
+    PyTime_TimeRaw(&self->timestamp_ns);  /* fills in 0 on failure. */
     self->traceback = self->cause = self->context = NULL;
     self->suppress_context = 0;
 
@@ -83,6 +84,7 @@ BaseException_init(PyBaseExceptionObject *self, PyObject *args, PyObject *kwds)
         return -1;
 
     Py_XSETREF(self->args, Py_NewRef(args));
+    PyTime_TimeRaw(&self->timestamp_ns);  /* fills in 0 on failure. */
     return 0;
 }
 
@@ -105,6 +107,7 @@ BaseException_vectorcall(PyObject *type_obj, PyObject * const*args,
     // The dict is created on the fly in PyObject_GenericSetAttr()
     self->dict = NULL;
     self->notes = NULL;
+    PyTime_TimeRaw(&self->timestamp_ns);  /* fills in 0 on failure. */
     self->traceback = NULL;
     self->cause = NULL;
     self->context = NULL;
@@ -184,11 +187,13 @@ BaseException_repr(PyBaseExceptionObject *self)
     Py_BEGIN_CRITICAL_SECTION(self);
     const char *name = _PyType_Name(Py_TYPE(self));
     if (PyTuple_GET_SIZE(self->args) == 1) {
-        res = PyUnicode_FromFormat("%s(%R)", name,
-                                    PyTuple_GET_ITEM(self->args, 0));
+        res = PyUnicode_FromFormat("%s(%R) [@t=%lldns]", name,
+                                    PyTuple_GET_ITEM(self->args, 0),
+                                    self->timestamp_ns);
     }
     else {
-        res = PyUnicode_FromFormat("%s%R", name, self->args);
+        res = PyUnicode_FromFormat("%s%R [@t=%lldns]", name, self->args,
+                                   self->timestamp_ns);
     }
     Py_END_CRITICAL_SECTION();
     return res;
@@ -597,6 +602,8 @@ PyExceptionClass_Name(PyObject *ob)
 static struct PyMemberDef BaseException_members[] = {
     {"__suppress_context__", Py_T_BOOL,
      offsetof(PyBaseExceptionObject, suppress_context)},
+    {"__timestamp_ns__", Py_T_LONGLONG,
+     offsetof(PyBaseExceptionObject, timestamp_ns)},
     {NULL}
 };