Skip to content

gh-102567: Add -X importtime=2 for logging an importtime message for already-loaded modules #133443

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 6 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 9 additions & 3 deletions Doc/c-api/init_config.rst
Original file line number Diff line number Diff line change
Expand Up @@ -363,7 +363,7 @@ Configuration Options
- Read-only
* - ``"import_time"``
- :c:member:`import_time <PyConfig.import_time>`
- ``bool``
- ``int``
- Read-only
* - ``"inspect"``
- :c:member:`inspect <PyConfig.inspect>`
Expand Down Expand Up @@ -1477,13 +1477,19 @@ PyConfig

.. c:member:: int import_time

If non-zero, profile import time.
If ``1``, profile import time.
If ``2``, include additional output that indicates
when an imported module has already been loaded.

Set the ``1`` by the :option:`-X importtime <-X>` option and the
Set by the :option:`-X importtime <-X>` option and the
:envvar:`PYTHONPROFILEIMPORTTIME` environment variable.

Default: ``0``.

.. versionchanged:: next

Added support for ``import_time = 2``

.. c:member:: int inspect

Enter interactive mode after executing a script or a command.
Expand Down
23 changes: 19 additions & 4 deletions Doc/using/cmdline.rst
Original file line number Diff line number Diff line change
Expand Up @@ -539,11 +539,21 @@ Miscellaneous options
* ``-X importtime`` to show how long each import takes. It shows module
name, cumulative time (including nested imports) and self time (excluding
nested imports). Note that its output may be broken in multi-threaded
application. Typical usage is ``python3 -X importtime -c 'import
asyncio'``. See also :envvar:`PYTHONPROFILEIMPORTTIME`.
application. Typical usage is ``python -X importtime -c 'import asyncio'``.

``-X importtime=2`` enables additional output that indicates when an
imported module has already been loaded. In such cases, the string
``cached`` will be printed in both time columns.

See also :envvar:`PYTHONPROFILEIMPORTTIME`.

.. versionadded:: 3.7

.. versionchanged:: next

Added ``-X importtime=2`` to also trace imports of loaded modules,
and reserved values other than ``1`` and ``2`` for future use.

* ``-X dev``: enable :ref:`Python Development Mode <devmode>`, introducing
additional runtime checks that are too expensive to be enabled by
default. See also :envvar:`PYTHONDEVMODE`.
Expand Down Expand Up @@ -984,12 +994,17 @@ conflict.

.. envvar:: PYTHONPROFILEIMPORTTIME

If this environment variable is set to a non-empty string, Python will
show how long each import takes.
If this environment variable is set to ``1``, Python will show
how long each import takes. If set to ``2``, Python will include output for
imported modules that have already been loaded.
This is equivalent to setting the :option:`-X` ``importtime`` option.

.. versionadded:: 3.7

.. versionchanged:: next

Added ``PYTHONPROFILEIMPORTTIME=2`` to also trace imports of loaded modules.


.. envvar:: PYTHONASYNCIODEBUG

Expand Down
7 changes: 7 additions & 0 deletions Doc/whatsnew/3.14.rst
Original file line number Diff line number Diff line change
Expand Up @@ -789,6 +789,13 @@ Other language changes
of HMAC is not available.
(Contributed by Bénédikt Tran in :gh:`99108`.)

* The import time flag can now track modules that are already loaded ('cached'),
via the new :option:`-X importtime=2 <-X>`.
When such a module is imported, the ``self`` and ``cumulative`` times
are replaced by the string ``cached``.
Values above ``2`` for ``-X importtime`` are now reserved for future use.
(Contributed by Noah Kim and Adam Turner in :gh:`118655`.)

* When subclassing from a pure C type, the C slots for the new type are no
longer replaced with a wrapped version on class creation if they are not
explicitly overridden in the subclass.
Expand Down
15 changes: 10 additions & 5 deletions Lib/_pyrepl/unix_console.py
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,7 @@
import struct
import termios
import time
import types
import platform
from fcntl import ioctl

Expand All @@ -39,6 +40,12 @@
from .unix_eventqueue import EventQueue
from .utils import wlen

# declare posix optional to allow None assignment on other platforms
posix: types.ModuleType | None
try:
import posix
except ImportError:
posix = None

TYPE_CHECKING = False

Expand Down Expand Up @@ -550,11 +557,9 @@ def clear(self):

@property
def input_hook(self):
try:
import posix
except ImportError:
return None
if posix._is_inputhook_installed():
# avoid inline imports here so the repl doesn't get flooded
# with import logging from -X importtime=2
if posix is not None and posix._is_inputhook_installed():
return posix._inputhook

def __enable_bracketed_paste(self) -> None:
Expand Down
18 changes: 11 additions & 7 deletions Lib/_pyrepl/windows_console.py
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@
import sys

import ctypes
import types
from ctypes.wintypes import (
_COORD,
WORD,
Expand Down Expand Up @@ -58,6 +59,12 @@ def __init__(self, err: int | None, descr: str | None = None) -> None:
self.err = err
self.descr = descr

# declare nt optional to allow None assignment on other platforms
nt: types.ModuleType | None
try:
import nt
except ImportError:
nt = None

TYPE_CHECKING = False

Expand Down Expand Up @@ -121,9 +128,8 @@ class _error(Exception):

def _supports_vt():
try:
import nt
return nt._supports_virtual_terminal()
except (ImportError, AttributeError):
except AttributeError:
return False

class WindowsConsole(Console):
Expand Down Expand Up @@ -235,11 +241,9 @@ def refresh(self, screen: list[str], c_xy: tuple[int, int]) -> None:

@property
def input_hook(self):
try:
import nt
except ImportError:
return None
if nt._is_inputhook_installed():
# avoid inline imports here so the repl doesn't get flooded
# with import logging from -X importtime=2
if nt is not None and nt._is_inputhook_installed():
return nt._inputhook

def __write_changed_line(
Expand Down
2 changes: 1 addition & 1 deletion Lib/test/test_capi/test_config.py
Original file line number Diff line number Diff line change
Expand Up @@ -57,7 +57,7 @@ def test_config_get(self):
("home", str | None, None),
("thread_inherit_context", int, None),
("context_aware_warnings", int, None),
("import_time", bool, None),
("import_time", int, None),
("inspect", bool, None),
("install_signal_handlers", bool, None),
("int_max_str_digits", int, None),
Expand Down
18 changes: 18 additions & 0 deletions Lib/test/test_cmd_line.py
Original file line number Diff line number Diff line change
Expand Up @@ -1158,6 +1158,24 @@ def test_cpu_count_default(self):
res = assert_python_ok('-c', code, PYTHON_CPU_COUNT='default')
self.assertEqual(self.res2int(res), (os.cpu_count(), os.process_cpu_count()))

def test_import_time(self):
# os is not imported at startup
code = 'import os; import os'

for case in 'importtime', 'importtime=1', 'importtime=true':
res = assert_python_ok('-X', case, '-c', code)
res_err = res.err.decode('utf-8')
self.assertRegex(res_err, r'import time: \s*\d+ \| \s*\d+ \| \s*os')
self.assertNotRegex(res_err, r'import time: cached\s* \| cached\s* \| os')

res = assert_python_ok('-X', 'importtime=2', '-c', code)
res_err = res.err.decode('utf-8')
self.assertRegex(res_err, r'import time: \s*\d+ \| \s*\d+ \| \s*os')
self.assertRegex(res_err, r'import time: cached\s* \| cached\s* \| os')

assert_python_failure('-X', 'importtime=-1', '-c', code)
assert_python_failure('-X', 'importtime=3', '-c', code)

def res2int(self, res):
out = res.out.strip().decode("utf-8")
return tuple(int(i) for i in out.split())
Expand Down
8 changes: 4 additions & 4 deletions Lib/test/test_embed.py
Original file line number Diff line number Diff line change
Expand Up @@ -585,7 +585,7 @@ class InitConfigTests(EmbeddingTestsMixin, unittest.TestCase):
'faulthandler': False,
'tracemalloc': 0,
'perf_profiling': 0,
'import_time': False,
'import_time': 0,
'thread_inherit_context': DEFAULT_THREAD_INHERIT_CONTEXT,
'context_aware_warnings': DEFAULT_CONTEXT_AWARE_WARNINGS,
'code_debug_ranges': True,
Expand Down Expand Up @@ -998,7 +998,7 @@ def test_init_from_config(self):
'hash_seed': 123,
'tracemalloc': 2,
'perf_profiling': 0,
'import_time': True,
'import_time': 2,
'code_debug_ranges': False,
'show_ref_count': True,
'malloc_stats': True,
Expand Down Expand Up @@ -1064,7 +1064,7 @@ def test_init_compat_env(self):
'use_hash_seed': True,
'hash_seed': 42,
'tracemalloc': 2,
'import_time': True,
'import_time': 1,
'code_debug_ranges': False,
'malloc_stats': True,
'inspect': True,
Expand Down Expand Up @@ -1100,7 +1100,7 @@ def test_init_python_env(self):
'use_hash_seed': True,
'hash_seed': 42,
'tracemalloc': 2,
'import_time': True,
'import_time': 1,
'code_debug_ranges': False,
'malloc_stats': True,
'inspect': True,
Expand Down
1 change: 1 addition & 0 deletions Lib/test/test_support.py
Original file line number Diff line number Diff line change
Expand Up @@ -561,6 +561,7 @@ def test_args_from_interpreter_flags(self):
['-Wignore', '-X', 'dev'],
['-X', 'faulthandler'],
['-X', 'importtime'],
['-X', 'importtime=2'],
['-X', 'showrefcount'],
['-X', 'tracemalloc'],
['-X', 'tracemalloc=3'],
Expand Down
1 change: 1 addition & 0 deletions Misc/ACKS
Original file line number Diff line number Diff line change
Expand Up @@ -966,6 +966,7 @@ Beomsoo Bombs Kim
Derek D. Kim
Gihwan Kim
Jan Kim
Noah Kim
Taek Joo Kim
Yeojin Kim
Sam Kimbrel
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,4 @@
:option:`-X importtime <-X>` now accepts value ``2``, which indicates that
an ``importtime`` entry should also be printed if an imported module has
already been loaded.
Patch by Noah Kim and Adam Turner.
11 changes: 8 additions & 3 deletions Misc/python.man
Original file line number Diff line number Diff line change
Expand Up @@ -344,6 +344,10 @@ Set implementation-specific option. The following options are available:
application. Typical usage is
\fBpython3 \-X importtime \-c 'import asyncio'\fR

\fB\-X importtime=2\fR enables additional output that indicates when an
imported module has already been loaded. In such cases, the string
\fBcached\fR will be printed in both time columns.

\fB\-X faulthandler\fR: enable faulthandler

\fB\-X frozen_modules=\fR[\fBon\fR|\fBoff\fR]: whether or not frozen modules
Expand Down Expand Up @@ -648,9 +652,10 @@ See also the \fB\-X perf\fR option.
.IP PYTHONPLATLIBDIR
Override sys.platlibdir.
.IP PYTHONPROFILEIMPORTTIME
If this environment variable is set to a non-empty string, Python will
show how long each import takes. This is exactly equivalent to setting
\fB\-X importtime\fP on the command line.
If this environment variable is set to \fB1\fR, Python will show
how long each import takes. If set to \fB2\fR, Python will include output for
imported modules that have already been loaded.
This is exactly equivalent to setting \fB\-X importtime\fP on the command line.
.IP PYTHONPYCACHEPREFIX
If this is set, Python will write \fB.pyc\fR files in a mirror directory tree
at this path, instead of in \fB__pycache__\fR directories within the source
Expand Down
4 changes: 2 additions & 2 deletions Programs/_testembed.c
Original file line number Diff line number Diff line change
Expand Up @@ -651,8 +651,8 @@ static int test_init_from_config(void)
putenv("PYTHONTRACEMALLOC=0");
config.tracemalloc = 2;

putenv("PYTHONPROFILEIMPORTTIME=0");
config.import_time = 1;
putenv("PYTHONPROFILEIMPORTTIME=1");
config.import_time = 2;

putenv("PYTHONNODEBUGRANGES=0");
config.code_debug_ranges = 0;
Expand Down
36 changes: 28 additions & 8 deletions Python/import.c
Original file line number Diff line number Diff line change
Expand Up @@ -103,6 +103,15 @@ static struct _inittab *inittab_copy = NULL;
#define FIND_AND_LOAD(interp) \
(interp)->imports.find_and_load

#define _IMPORT_TIME_HEADER(interp) \
do { \
if (FIND_AND_LOAD((interp)).header) { \
fputs("import time: self [us] | cumulative | imported package\n", \
stderr); \
FIND_AND_LOAD((interp)).header = 0; \
} \
} while (0)


/*******************/
/* the import lock */
Expand Down Expand Up @@ -246,16 +255,33 @@ import_ensure_initialized(PyInterpreterState *interp, PyObject *mod, PyObject *n
rc = _PyModuleSpec_IsInitializing(spec);
Py_DECREF(spec);
}
if (rc <= 0) {
if (rc == 0) {
goto done;
}
else if (rc < 0) {
return rc;
}

/* Wait until module is done importing. */
PyObject *value = PyObject_CallMethodOneArg(
IMPORTLIB(interp), &_Py_ID(_lock_unlock_module), name);
if (value == NULL) {
return -1;
}
Py_DECREF(value);

done:
/* When -X importtime=2, print an import time entry even if an
imported module has already been loaded.
*/
if (_PyInterpreterState_GetConfig(interp)->import_time == 2) {
_IMPORT_TIME_HEADER(interp);
#define import_level FIND_AND_LOAD(interp).import_level
fprintf(stderr, "import time: cached | cached | %*s\n",
import_level*2, PyUnicode_AsUTF8(name));
#undef import_level
}

return 0;
}

Expand Down Expand Up @@ -3686,13 +3712,7 @@ import_find_and_load(PyThreadState *tstate, PyObject *abs_name)
* _PyDict_GetItemIdWithError().
*/
if (import_time) {
#define header FIND_AND_LOAD(interp).header
if (header) {
fputs("import time: self [us] | cumulative | imported package\n",
stderr);
header = 0;
}
#undef header
_IMPORT_TIME_HEADER(interp);

import_level++;
// ignore error: don't block import if reading the clock fails
Expand Down
Loading
Loading