GeezerVison

Unfortunately the lazy import fails when trying to test logging during shutdown:

======================================================================
FAIL: test_logging_at_shutdown (test.test_logging.ModuleLevelMiscTest.test_logging_at_shutdown)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/runner/work/cpython/cpython/Lib/test/test_logging.py", line 5259, in test_logging_at_shutdown
    self.assertIn("exception in __del__", err)
    ~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: 'exception in __del__' not found in '--- Logging error ---\nException ignored while calling deallocator <function A.__del__ at 0x20002d3e8d0>:\nTraceback (most recent call last):\n  File "<string>", line 9, in __del__\n  File "/Users/runner/work/cpython/cpython/Lib/logging/__init__.py", line 2194, in exception\n  File "/Users/runner/work/cpython/cpython/Lib/logging/__init__.py", line 2186, in error\n  File "/Users/runner/work/cpython/cpython/Lib/logging/__init__.py", line 1553, in error\n  File "/Users/runner/work/cpython/cpython/Lib/logging/__init__.py", line 1669, in _log\n  File "/Users/runner/work/cpython/cpython/Lib/logging/__init__.py", line 1685, in handle\n  File "/Users/runner/work/cpython/cpython/Lib/logging/__init__.py", line 1741, in callHandlers\n  File "/Users/runner/work/cpython/cpython/Lib/logging/__init__.py", line 1031, in handle\n  File "/Users/runner/work/cpython/cpython/Lib/logging/__init__.py", line 1163, in emit\n  File "/Users/runner/work/cpython/cpython/Lib/logging/__init__.py", line 1080, in handleError\nImportError: sys.meta_path is None, Python is likely shutting down\n'

We can fix the test by adding atexit.register(lambda: traceback) in __init__.py, which guarantees traceback will be imported before the interpreter cleans up. But sadly, the wall-clock time will still be unoptimized in that case.

I would prefer that we do not overcomplicate atexit callbacks in this case.

I see your performance improvement figure in the issue - why is a few ms at application start time an issue? How much time do you practically save in a realistic application?

It helps for CLIs, and especially for --help which should usually be a no-op.

Some report 50ms delays can be noticeable, and 10-20ms sometimes be distinguished from 5ms or lower, when it comes to interactivity.

https://danluu.com/term-latency/
https://xyrillian.de/thoughts/posts/latency-matters.html

More conservatively, 100ms is often cited as a response time limit

https://www.nngroup.com/articles/response-times-3-important-limits/

CLI tools are sometimes (re-)written in languages like Rust or Go rather than Python or Node because of these lower millisecond times.

Slicing off 13ms here doesn't necessarily improve things on its own, but it's a fair chunk of 100ms, and it all adds up.

And especially as logging is so widely used, so if we can save here, then it benefits many.

Another use case is serverless computing, which can be billed by the millisecond.

@ByteFlowing1337 What OS did you use for the charts in #150072? Are they from debug or optimised builds of Python.

It helps for CLIs, and especially for --help which should usually be a no-op.

Exactly! That's why I wanna optimize it.

The figure showed in the issue was tested on the debug builds of python on Linux (WSL2).

On Linux (WSL2), with an optimized Python build, we obtained the following results:

Before (12ms)	After (6ms)

As a result, this optimization shaves off roughly only 6ms.

Before #149318 was merged, importing logging is much slower than the current main branch, as _colorize is eagerly imported in traceback. Tested on official Windows release of python 3.14.4:

As a result, this optimization shaves off roughly only 6ms.

I think 6ms saving would be good if was just a matter of adding lazy but the shutdown issue complicates it (and I had already tried it and prioritised other things for this reason :)

Before #149318 was merged, importing logging is much slower than the current main branch, as _colorize is eagerly imported in traceback. Tested on official Windows release of python 3.14.4:

Yeah, the traceback improvement was partly motivated by indirectly improving logging.

See also my previous (unsuccessful) attempt at this and the discussion in #112995

Instead of lazily importing it, what happens if you remove the import at the top of the module and just import it normally in the suites where it's referenced? Is it the same error on shutdown?

Instead of lazily importing it, what happens if you remove the import at the top of the module and just import it normally in the suites where it's referenced? Is it the same error on shutdown?

That what I did in #112995 and it doesn't work. Ultimately, inlining the imports into the functions is basically equivalent of having a lazy import at the top. I don't see a way around this TBH. I am actually in general surprised/worried that we don't see more issues at interpreter shutdown given that we now make more and more imports lazy in stdlib.

Would lazy importing re within the logging module be a safer alternative?
It's not as big of a win but it's the next best thing.

logging eagerly imports traceback which eagerly imports re, so it ends up reified anyway.

Lazily importing traceback in logging fails test_logging_at_shutdown.

This PR is stale because it has been open for 90 days with no activity.