diff --git a/.github/CODEOWNERS b/.github/CODEOWNERS index 8087be96d53..55897871a0e 100644 --- a/.github/CODEOWNERS +++ b/.github/CODEOWNERS @@ -703,6 +703,7 @@ peps/pep-0826.rst @savannahostrowski peps/pep-0827.rst @1st1 peps/pep-0828.rst @ZeroIntensity peps/pep-0829.rst @warsaw +peps/pep-0830.rst @gpshead # ... peps/pep-2026.rst @hugovk # ... diff --git a/peps/pep-0830.rst b/peps/pep-0830.rst new file mode 100644 index 00000000000..f9080fd84de --- /dev/null +++ b/peps/pep-0830.rst @@ -0,0 +1,413 @@ +PEP: 830 +Title: Add timestamps to exceptions and tracebacks +Author: Gregory P. Smith +Discussions-To: Pending +Status: Draft +Type: Standards Track +Created: 15-Mar-2026 +Python-Version: 3.15 +Post-History: + + +Abstract +======== + +This PEP adds an optional ``__timestamp_ns__`` attribute to ``BaseException`` +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. + + +Motivation +========== + +With the introduction of exception groups (:pep:`654`), Python programs can now +propagate multiple unrelated exceptions simultaneously. When debugging these, +or when correlating exceptions with external logs and metrics, knowing *when* +each exception occurred is often as important as knowing *what* occurred; +a common pain point when diagnosing problems in production. + +Currently there is no standard way to obtain this information. Python authors +must manually add timing to exception messages or rely on logging frameworks, +which can be costly and is inconsistently done and error-prone. + +Consider an async service that fetches data from multiple backends concurrently +using ``asyncio.TaskGroup``. When several backends fail, the resulting +``ExceptionGroup`` contains all the errors but no indication of their temporal +ordering:: + + import asyncio + + async def fetch_user(uid): + await asyncio.sleep(0.5) + raise ConnectionError(f"User service timeout for {uid}") + + async def fetch_orders(uid): + await asyncio.sleep(0.1) + raise ValueError(f"Invalid user_id format: {uid}") + + async def fetch_recommendations(uid): + await asyncio.sleep(2.3) + raise TimeoutError("Recommendation service timeout") + + async def fetch_inventory(items): + await asyncio.sleep(0.8) + raise KeyError("Item 'widget-42' not found in inventory") + + async def get_dashboard(uid): + async with asyncio.TaskGroup() as tg: + tg.create_task(fetch_user(uid)) + tg.create_task(fetch_orders(uid)) + tg.create_task(fetch_recommendations(uid)) + tg.create_task(fetch_inventory(['widget-42'])) + +With ``PYTHON_TRACEBACK_TIMESTAMPS=iso``, the output becomes: + +.. code-block:: text + + Traceback (most recent call last): + ... + ExceptionGroup: unhandled errors in a TaskGroup (4 sub-exceptions) + +-+---------------- 1 ---------------- + | Traceback (most recent call last): + | File "service.py", line 11, in fetch_orders + | raise ValueError(f"Invalid user_id format: {uid}") + | ValueError: Invalid user_id format: usr_12@34 <@2025-03-15T10:23:41.142857Z> + +---------------- 2 ---------------- + | Traceback (most recent call last): + | File "service.py", line 7, in fetch_user + | raise ConnectionError(f"User service timeout for {uid}") + | ConnectionError: User service timeout for usr_12@34 <@2025-03-15T10:23:41.542901Z> + +---------------- 3 ---------------- + | Traceback (most recent call last): + | File "service.py", line 19, in fetch_inventory + | raise KeyError("Item 'widget-42' not found in inventory") + | KeyError: "Item 'widget-42' not found in inventory" <@2025-03-15T10:23:41.842856Z> + +---------------- 4 ---------------- + | Traceback (most recent call last): + | File "service.py", line 15, in fetch_recommendations + | raise TimeoutError("Recommendation service timeout") + | TimeoutError: Recommendation service timeout <@2025-03-15T10:23:43.342912Z> + +The timestamps immediately reveal that the order validation failed first +(at .142s), while the recommendation service was the slowest at 2.3 seconds. +That could also be correlated with metrics dashboards, load balancer logs, or +traces from other services or even logs from the program itself to build a +complete picture. + + +Specification +============= + +Exception Timestamp Attribute +----------------------------- + +A new read/write attribute ``__timestamp_ns__`` is added to ``BaseException``. +It stores nanoseconds since the Unix epoch (same precision as +``time.time_ns()``) as a C ``int64_t`` exposed via a member descriptor. When +timestamps are disabled, or for control flow exceptions (see below), the value +is ``0``. + +Control Flow Exceptions +------------------------ + +To avoid performance impact on normal control flow, timestamps are **not** +collected for ``StopIteration`` or ``StopAsyncIteration`` even when the feature +is enabled. These exceptions are raised at extremely high frequency during +iteration; the check uses C type pointer identity (not ``isinstance``) for +negligible overhead. + +Configuration +------------- + +The feature is enabled through CPython's two standard mechanisms: + +``PYTHON_TRACEBACK_TIMESTAMPS`` environment variable + Set to ``us`` or ``1`` for microsecond-precision decimal timestamps, + ``ns`` for nanoseconds, or ``iso`` for ISO 8601 UTC format. + Empty, unset, or ``0`` disables timestamps (the default). + +``-X traceback_timestamps=`` command-line option + Accepts the same values. Takes precedence over the environment variable. + If ``-X traceback_timestamps`` is specified with no ``=`` value, + that acts as an implicit ``=1`` (microsecond-precision format). + +Consistent with other CPython config behavior, an invalid environment variable +value is silently ignored while an invalid ``-X`` flag value is an error. + +A new ``traceback_timestamps`` field in ``PyConfig`` stores the selected format, +accessible as ``sys.flags.traceback_timestamps``. + +Display Format +-------------- + +Timestamps are appended to the exception message line in tracebacks using +the format ``<@timestamp>``. Example with ``iso``: + +.. code-block:: text + + Traceback (most recent call last): + File "", line 3, in california_raisin + raise RuntimeError("not enough sunshine") + RuntimeError: not enough sunshine <@2026-04-12T18:07:30.346914Z> + +When colorized output is enabled, the timestamp is rendered in a muted color +to keep it visually distinct from the exception message. + +The ``us`` format produces ``<@1776017164.530916>`` and the ``ns`` format +produces ``<@1776017178687320256ns>``. + +Traceback Module Updates +------------------------ + +``TracebackException`` and the public formatting functions (``print_exc``, +``print_exception``, ``format_exception``, ``format_exception_only``) gain a +``no_timestamp`` keyword argument (default ``False``) that suppresses timestamp +display even when globally enabled. + +A new utility function ``traceback.strip_exc_timestamps(text)`` is provided +to strip ``<@...>`` timestamp suffixes from formatted traceback strings. +This is useful for anything that compares traceback output literally. + +Doctest Updates +--------------- + +A new ``doctest.IGNORE_EXCEPTION_TIMESTAMPS`` option flag is added. When +enabled, the doctest output checker strips timestamps from actual output before +comparison, so that doctests producing exceptions pass regardless of whether +timestamps are enabled. + +Third-party projects are **not** expected to support running their tests with +timestamps enabled, and we do not expect many projects would ever want to. + + +Rationale +========= + +The timestamp is stored as a single ``int64_t`` field in the ``BaseException`` +C struct, recording nanoseconds since the Unix epoch. This design was chosen +over using exception notes (:pep:`678`) because a struct field costs nothing +when not populated, avoids creating string and list objects at raise time, and +defers all formatting work to traceback rendering. The feature is entirely +opt-in and does not change exception handling semantics. + +The use of exception notes as a carrier for the information was deemed +infeasible due to their performance overhead and lack of explicit purpose. +Notes are great, but were designed for a far different use case, not as a +way to collect data captured upon every Exception instantiation. + +Performance Measurements +------------------------ + +The pyperformance suite has been run on the merge base, on the PR branch with +the feature disabled, and on the PR branch with the feature enabled in both +``us`` and ``iso`` modes. + +There were no significant performance changes observed by this author. Just +occasional varying 1-2% measurement noise that could not be reliably +reproduced. Below the benchmarking setup noise threshold as far as the author +is concerned. + +What about the special case performance optimiaztion? If I omit the two line +special case to avoid collecting timestamps on ``StopIteration`` and +``StopAsyncIteration`` in ``Objects/exception.c``, only a single benchmark +showed a regression: ``async_generators``. That one would reliably run on the +order of 10% slower without that optimization. It is likely effectively a +microbenchmark that does not reflect most application behavior. Regardless, it +demonstrates the importance of that optimization. + +I used ``configure --enable-optimizations`` builds for my benchmarks and ran +them using commands such as: + +.. code-block:: text + + pyperformance run -p baseline-3a7df632c96/build/python -o baseline-eopt.json + pyperformance run -p traceback-timestamps/build/python -o traceback-timestamps-default-eopt.json + PYTHON_TRACEBACK_TIMESTAMPS=1 pyperformance run --inherit-environ PYTHON_TRACEBACK_TIMESTAMPS -p traceback-timestamps/build/python -o traceback-timestamps-env=1-eopt.json + PYTHON_TRACEBACK_TIMESTAMPS=iso pyperformance run --inherit-environ PYTHON_TRACEBACK_TIMESTAMPS -p traceback-timestamps/build/python -o traceback-timestamps/Results.silencio/traceback-timestamps-env=iso-eopt.json + PYTHON_TRACEBACK_TIMESTAMPS=1 pyperformance run --inherit-environ PYTHON_TRACEBACK_TIMESTAMPS -p traceback-timestamps-without-StopIter-cases/build/python -o traceback-timestamps/Results.silencio/traceback-timestamps-without-StopIter-cases-env=1-eopt.json + + +Backwards Compatibility +======================= + +The feature is disabled by default and does not affect existing exception +handling code. The ``__timestamp_ns__`` attribute is always readable on +``BaseException`` instances, returning ``0`` when timestamps are not collected. + +When timestamps are disabled, exceptions pickle in the traditional 2-tuple +format ``(type, args)``. When a nonzero timestamp is present, exceptions +pickle as ``(type, args, state_dict)`` with ``__timestamp_ns__`` in the state +dictionary. Older Python versions unpickle these correctly via +``__setstate__``. Always emitting the 3-tuple form (with a zero timestamp) +would simplify the logic, but was avoided to keep the pickle output +byte-identical when the feature is off and to avoid any performance impact +on the common case. As much as this author prefers simpler code, it felt +riskier to have exception pickles all increase in size as a default behavior. + +Pickled Exception Examples +-------------------------- + +With traceback timestamp collection enabled: + +.. code-block:: text + + ❯ build/python -X traceback_timestamps=iso -c 'import pickle; print(pickle.dumps(RuntimeError("pep-830"), protocol=pickle.HIGHEST_PROTOCOL))' + b'\x80\x05\x95L\x00\x00\x00\x00\x00\x00\x00\x8c\x08builtins\x94\x8c\x0cRuntimeError\x94\x93\x94\x8c\x07pep-830\x94\x85\x94R\x94}\x94\x8c\x10__timestamp_ns__\x94\x8a\x08\xf4\xd8\x94`\x15\xaf\xa5\x18sb.' + +The special case for ``StopIteration`` means it does not carry the dict with timestamp data: + +.. code-block:: text + + ❯ build/python -X traceback_timestamps=iso -c 'import pickle; print(pickle.dumps(StopIteration("pep-830"), protocol=pickle.HIGHEST_PROTOCOL))' + b'\x80\x05\x95,\x00\x00\x00\x00\x00\x00\x00\x8c\x08builtins\x94\x8c\rStopIteration\x94\x93\x94\x8c\x07pep-830\x94\x85\x94R\x94.' + +Nor do exceptions carry the timestamp when the feature is disabled (the default): + +.. code-block:: text + + ❯ build/python -X traceback_timestamps=0 -c 'import pickle; print(pickle.dumps(RuntimeError("pep-830"), protocol=pickle.HIGHEST_PROTOCOL))' + b'\x80\x05\x95+\x00\x00\x00\x00\x00\x00\x00\x8c\x08builtins\x94\x8c\x0cRuntimeError\x94\x93\x94\x8c\x07pep-830\x94\x85\x94R\x94.' + +Which matches what Python 3.13 produces: + +.. code-block:: text + + ❯ python3.13 -c 'import pickle; print(pickle.dumps(RuntimeError("pep-830"), protocol=pickle.HIGHEST_PROTOCOL))' + b'\x80\x05\x95+\x00\x00\x00\x00\x00\x00\x00\x8c\x08builtins\x94\x8c\x0cRuntimeError\x94\x93\x94\x8c\x07pep-830\x94\x85\x94R\x94.' + +Maintenance Burden +------------------ + +The ``__timestamp_ns__`` field is a single ``int64_t`` in the ``BaseException`` +C struct, present in every exception object regardless of configuration. The +collection code is a guarded ``clock_gettime`` call; the formatting code only +runs at traceback display time. Both are small and self-contained. + +The main ongoing cost is in the test suite. Tests that compare traceback +output literally need to account for the optional timestamp suffix. Two +helpers are provided for this: + +- ``traceback.strip_exc_timestamps(text)`` strips ``<@...>`` suffixes from + formatted traceback strings. +- ``test.support.force_no_traceback_timestamps`` and a ``_test_class`` suffixed + variant are decorators that disable timestamp collection for the duration of + a test or ``TestCase`` class. + +Outside of the traceback-specific tests, approximately 14 of ~1230 test files +(roughly 1%) needed one of these helpers, typically tests that capture +``stderr`` and match against expected traceback output (e.g. ``test_logging``, +``test_repl``, ``test_wsgiref``, ``test_threading``). The pattern follows the same approach used by ``force_not_colorized`` for +ANSI color codes in tracebacks. + +Outside of CPython's own CI, where timestamps are enabled on a couple of +GitHub Actions runs to maintain coverage, most projects are unlikely to +have the feature enabled while running their test suites. + + +Security Implications +===================== + +None. The feature is opt-in and disabled by default. + + +How to Teach This +================= + +The ``__timestamp_ns__`` attribute and configuration options will be documented +in the ``exceptions`` module reference, the ``traceback`` module reference, +and the command-line interface documentation. + +This is a power feature: disabled by default and invisible unless explicitly +enabled. It does not need to be covered in introductory material. + + +Reference Implementation +======================== + +`CPython PR #129337 `_. + + +Rejected Ideas +============== + +Using Exception Notes +--------------------- + +Using :pep:`678`'s ``.add_note()`` to attach timestamps was rejected for +several reasons. Notes require creating string and list objects at raise time, +imposing overhead even when timestamps are not displayed. Notes added when +*catching* an exception reflect the catch time, not the raise time, and in +async code this difference can be significant. Not all exceptions are caught +(some propagate to top level or are logged directly), so catch-time notes +would be applied inconsistently. A struct field captures the timestamp at the +source and defers all formatting to display time. + +Always Collecting vs. Always Displaying +---------------------------------------- + +*Collecting* timestamps (a ``clock_gettime`` call during instantiation) and +*displaying* them in formatted tracebacks are separate concerns. + +Always displaying was rejected because it adds noise that most users do not +need. Always collecting (even when display is disabled) is cheap since the +``int64_t`` field exists in the struct regardless, but not collecting avoids +any potential for performance impact when the feature is turned off, and there +is no current reason to collect timestamps that will never be shown. This could be +revisited if programmatic access to exception timestamps becomes useful +independent of traceback display. + +Runtime API +----------- + +A Python API to toggle timestamps at runtime is unnecessary complexity. +Applications that want timestamps are expected to enable them in their +environment; a runtime toggle would make it harder to reason about program +state. The feature is configured at startup and remains fixed. + +Custom Timestamp Formats +------------------------- + +User-defined format strings would add significant complexity. The three +built-in formats (``us``, ``ns``, ``iso``) cover the common needs: +human-readable decimal seconds, raw nanoseconds for programmatic use, and +ISO 8601 for correlation with external systems. + +Configurable Control Flow Exception Set +----------------------------------------- + +Allowing users to register additional exceptions to skip was rejected. The +exclusion check runs in the hot path of exception creation and uses C type +pointer identity for speed. Supporting a configurable set would require +either ``isinstance`` checks (too slow, walks the MRO) or a hash set of +type pointers (complexity with unclear benefit). ``StopIteration`` and +``StopAsyncIteration`` are the only exceptions raised at frequencies where +the cost of ``clock_gettime`` is measurable. If a practical need arises, an +API to register additional exclusions efficiently could be added as a follow-on +enhancement. + +Millisecond Precision +--------------------- + +Nanosecond precision was chosen over millisecond to match ``time.time_ns()`` +and to provide sufficient resolution for high-frequency exception scenarios. + + +Acknowledgements +================ + +Thanks to Nathaniel J. Smith for the original idea suggestion, and to +``@dcolascione`` for initial 2025 review feedback on the implementation. + + +Change History +============== + +the future is now + + +Copyright +========= + +This document is placed in the public domain or under the +CC0-1.0-Universal license, whichever is more permissive.