Skip to content

gh-150072: Optimize logging imports by lazily importing traceback#150073

Open
ByteFlowing1337 wants to merge 1 commit into
python:mainfrom
ByteFlowing1337:faster-logging
Open

gh-150072: Optimize logging imports by lazily importing traceback#150073
ByteFlowing1337 wants to merge 1 commit into
python:mainfrom
ByteFlowing1337:faster-logging

Conversation

@ByteFlowing1337
Copy link
Copy Markdown
Contributor

@ByteFlowing1337 ByteFlowing1337 commented May 19, 2026

@hugovk
Copy link
Copy Markdown
Member

hugovk commented May 19, 2026

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'

@ByteFlowing1337
Copy link
Copy Markdown
Contributor Author

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.

@picnixz
Copy link
Copy Markdown
Member

picnixz commented May 19, 2026

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

@vsajip
Copy link
Copy Markdown
Member

vsajip commented May 19, 2026

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?

@hugovk
Copy link
Copy Markdown
Member

hugovk commented May 19, 2026

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.

@ByteFlowing1337
Copy link
Copy Markdown
Contributor Author

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:

@hugovk
Copy link
Copy Markdown
Member

hugovk commented May 20, 2026

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.

@danielhollas
Copy link
Copy Markdown
Contributor

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

@vsajip
Copy link
Copy Markdown
Member

vsajip commented May 20, 2026

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?

@danielhollas
Copy link
Copy Markdown
Contributor

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants