gh-150072: Optimize logging imports by lazily importing traceback#150073
gh-150072: Optimize logging imports by lazily importing traceback#150073ByteFlowing1337 wants to merge 1 commit into
traceback#150073Conversation
|
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 |
|
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 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/ 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 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. |
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:
As a result, this optimization shaves off roughly only 6ms. Before #149318 was merged, importing
|
I think 6ms saving would be good if was just a matter of adding
Yeah, the |
|
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? |
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. |



tracebackinlogging#150072