From 58d07bec9da1623e5fac34b4658f110d78b28aeb Mon Sep 17 00:00:00 2001 From: Noah Kim Date: Mon, 6 May 2024 11:30:32 -0400 Subject: [PATCH 1/6] Add -X importtime=2 for logging an importtime message for already-loaded modules --- Doc/c-api/init_config.rst | 5 +- Doc/using/cmdline.rst | 18 ++++- Doc/whatsnew/3.14.rst | 7 ++ Lib/_pyrepl/unix_console.py | 16 ++-- Lib/_pyrepl/windows_console.py | 20 +++-- Lib/test/test_capi/test_config.py | 2 +- Lib/test/test_cmd_line.py | 22 ++++++ Lib/test/test_embed.py | 8 +- ...-07-11-12-31-29.gh-issue-102567.weRqDn.rst | 3 + Programs/_testembed.c | 2 +- Python/import.c | 18 ++++- Python/initconfig.c | 73 +++++++++++++++++-- 12 files changed, 163 insertions(+), 31 deletions(-) create mode 100644 Misc/NEWS.d/next/Core_and_Builtins/2024-07-11-12-31-29.gh-issue-102567.weRqDn.rst diff --git a/Doc/c-api/init_config.rst b/Doc/c-api/init_config.rst index bc5b236393be15..22a766822b712a 100644 --- a/Doc/c-api/init_config.rst +++ b/Doc/c-api/init_config.rst @@ -1477,9 +1477,10 @@ PyConfig .. c:member:: int import_time - If non-zero, profile import time. + If non-zero, 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``. diff --git a/Doc/using/cmdline.rst b/Doc/using/cmdline.rst index fa7c9cddf9c6d6..ebe178d9729231 100644 --- a/Doc/using/cmdline.rst +++ b/Doc/using/cmdline.rst @@ -542,8 +542,17 @@ Miscellaneous options application. Typical usage is ``python3 -X importtime -c 'import asyncio'``. See also :envvar:`PYTHONPROFILEIMPORTTIME`. + ``-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 the self time and cumulative time columns. + .. 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 `, introducing additional runtime checks that are too expensive to be enabled by default. See also :envvar:`PYTHONDEVMODE`. @@ -984,12 +993,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 diff --git a/Doc/whatsnew/3.14.rst b/Doc/whatsnew/3.14.rst index dad63e47a62dba..2f3df4fd36f3b5 100644 --- a/Doc/whatsnew/3.14.rst +++ b/Doc/whatsnew/3.14.rst @@ -626,6 +626,13 @@ Other language changes of HMAC is not available. (Contributed by Bénédikt Tran in :gh:`99108`.) +* :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. The ``self`` and ``cumulative`` times for such entries + are replaced by the string ``cached``. + Values above ``2`` are now reserved for future use. + (Contributed by Noah Kim 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. diff --git a/Lib/_pyrepl/unix_console.py b/Lib/_pyrepl/unix_console.py index 96379bc20f3357..a6a3c68c92d0f8 100644 --- a/Lib/_pyrepl/unix_console.py +++ b/Lib/_pyrepl/unix_console.py @@ -29,6 +29,7 @@ import struct import termios import time +import types import platform from fcntl import ioctl @@ -39,6 +40,13 @@ 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 @@ -566,11 +574,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 -Ximporttime=2 + if posix is not None and posix._is_inputhook_installed(): return posix._inputhook def __enable_bracketed_paste(self) -> None: diff --git a/Lib/_pyrepl/windows_console.py b/Lib/_pyrepl/windows_console.py index 17942c8df0731a..efadad629411dd 100644 --- a/Lib/_pyrepl/windows_console.py +++ b/Lib/_pyrepl/windows_console.py @@ -24,6 +24,7 @@ import sys import ctypes +import types from ctypes.wintypes import ( _COORD, WORD, @@ -58,6 +59,12 @@ def __init__(self, err: int | None, descr: str | None = None) -> None: self.err = err self.descr = descr +nt: types.ModuleType | None + +try: + import nt +except ImportError: + nt = None TYPE_CHECKING = False @@ -121,9 +128,8 @@ class _error(Exception): def _supports_vt(): try: - import nt - return nt._supports_virtual_terminal() - except (ImportError, AttributeError): + nt._supports_virtual_terminal() + except AttributeError: return False class WindowsConsole(Console): @@ -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 -Ximporttime=2 + if nt is not None and nt._is_inputhook_installed(): return nt._inputhook def __write_changed_line( diff --git a/Lib/test/test_capi/test_config.py b/Lib/test/test_capi/test_config.py index bf351c4defab5d..a2d70dd3af482d 100644 --- a/Lib/test/test_capi/test_config.py +++ b/Lib/test/test_capi/test_config.py @@ -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), diff --git a/Lib/test/test_cmd_line.py b/Lib/test/test_cmd_line.py index 36f87e259e794d..2dda393e7d13d0 100644 --- a/Lib/test/test_cmd_line.py +++ b/Lib/test/test_cmd_line.py @@ -1158,6 +1158,28 @@ 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): + code = "import os" + res = assert_python_ok('-X', 'importtime', '-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") + + code = "import os" + res = assert_python_ok('-X', 'importtime=true', '-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") + + code = "import os; import 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()) diff --git a/Lib/test/test_embed.py b/Lib/test/test_embed.py index e06e684408ca6b..4e6bf4d243bab7 100644 --- a/Lib/test/test_embed.py +++ b/Lib/test/test_embed.py @@ -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, @@ -998,7 +998,7 @@ def test_init_from_config(self): 'hash_seed': 123, 'tracemalloc': 2, 'perf_profiling': 0, - 'import_time': True, + 'import_time': 0, 'code_debug_ranges': False, 'show_ref_count': True, 'malloc_stats': True, @@ -1064,7 +1064,7 @@ def test_init_compat_env(self): 'use_hash_seed': True, 'hash_seed': 42, 'tracemalloc': 2, - 'import_time': True, + 'import_time': 0, 'code_debug_ranges': False, 'malloc_stats': True, 'inspect': True, @@ -1100,7 +1100,7 @@ def test_init_python_env(self): 'use_hash_seed': True, 'hash_seed': 42, 'tracemalloc': 2, - 'import_time': True, + 'import_time': 0, 'code_debug_ranges': False, 'malloc_stats': True, 'inspect': True, diff --git a/Misc/NEWS.d/next/Core_and_Builtins/2024-07-11-12-31-29.gh-issue-102567.weRqDn.rst b/Misc/NEWS.d/next/Core_and_Builtins/2024-07-11-12-31-29.gh-issue-102567.weRqDn.rst new file mode 100644 index 00000000000000..6141a80477aeae --- /dev/null +++ b/Misc/NEWS.d/next/Core_and_Builtins/2024-07-11-12-31-29.gh-issue-102567.weRqDn.rst @@ -0,0 +1,3 @@ +: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. diff --git a/Programs/_testembed.c b/Programs/_testembed.c index 6f6d0cae58010e..2d4a271b7fc49e 100644 --- a/Programs/_testembed.c +++ b/Programs/_testembed.c @@ -652,7 +652,7 @@ static int test_init_from_config(void) config.tracemalloc = 2; putenv("PYTHONPROFILEIMPORTTIME=0"); - config.import_time = 1; + config.import_time = 0; putenv("PYTHONNODEBUGRANGES=0"); config.code_debug_ranges = 0; diff --git a/Python/import.c b/Python/import.c index a671a08daeb50f..08d64d0d662d62 100644 --- a/Python/import.c +++ b/Python/import.c @@ -246,9 +246,13 @@ 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); @@ -256,6 +260,18 @@ import_ensure_initialized(PyInterpreterState *interp, PyObject *mod, PyObject *n return -1; } Py_DECREF(value); + +done: + /* When -Ximporttime=2, print an import time entry even if an + * imported module has already been loaded. + */ + if (_PyInterpreterState_GetConfig(interp)->import_time >= 2) { +#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; } diff --git a/Python/initconfig.c b/Python/initconfig.c index 7d3043dd5d1dd9..f12ae75524b3da 100644 --- a/Python/initconfig.c +++ b/Python/initconfig.c @@ -153,7 +153,7 @@ static const PyConfigSpec PYCONFIG_SPEC[] = { SPEC(home, WSTR_OPT, READ_ONLY, NO_SYS), SPEC(thread_inherit_context, INT, READ_ONLY, NO_SYS), SPEC(context_aware_warnings, INT, READ_ONLY, NO_SYS), - SPEC(import_time, BOOL, READ_ONLY, NO_SYS), + SPEC(import_time, UINT, READ_ONLY, NO_SYS), SPEC(install_signal_handlers, BOOL, READ_ONLY, NO_SYS), SPEC(isolated, BOOL, READ_ONLY, NO_SYS), // sys.flags.isolated #ifdef MS_WINDOWS @@ -312,7 +312,8 @@ The following implementation-specific options are available:\n\ "-X gil=[0|1]: enable (1) or disable (0) the GIL; also PYTHON_GIL\n" #endif "\ --X importtime: show how long each import takes; also PYTHONPROFILEIMPORTTIME\n\ +-X importtime[=2]: show how long each import takes; -X importtime=2 also prints\ + rows for imports of already-loaded modules; also PYTHONPROFILEIMPORTTIME\n\ -X int_max_str_digits=N: limit the size of int<->str conversions;\n\ 0 disables the limit; also PYTHONINTMAXSTRDIGITS\n\ -X no_debug_ranges: don't include extra location information in code objects;\n\ @@ -2246,6 +2247,63 @@ config_init_run_presite(PyConfig *config) } #endif +/* Set `config->import_time` based on `value` from `-Ximporttime(=.*)?`. */ +static PyStatus +config_set_import_time(PyConfig *config, const wchar_t *value) +{ + int numeric_value; + + // If no value is specified or the value is not an integer, use 1. + if (*value == 0 || config_wstr_to_int(value, &numeric_value) != 0) { + config->import_time = 1; + } + + /* -Ximporttime=1 incurs the default behavior. -Ximporttime=2 also + * prints import cache hits. All other numeric values are reserved. + */ + else if (0 <= numeric_value && numeric_value <= 2) { + config->import_time = numeric_value; + } + + else { + return _PyStatus_ERR( + "-X importtime: numeric values other than 1 or 2 are " + "reserved for future use"); + } + + return _PyStatus_OK(); +} + +/* Configure `config->import_time` by checking -Ximporttime then the + * PYTHONPROFILEIMPORTTIME environment variable. Defaults to 0. + */ +static PyStatus +config_read_import_time(PyConfig *config) +{ + /* Check the -X option first. */ + const wchar_t *xoption_value = NULL; + xoption_value = config_get_xoption_value(config, L"importtime"); + if (xoption_value != NULL) { + return config_set_import_time(config, xoption_value); + } + + /* If there's no -Ximporttime, look for ENV flag */ + wchar_t *env_value = NULL; + /* `CONFIG_GET_ENV_DUP` requires dest to be initialized to `NULL`. */ + PyStatus status = CONFIG_GET_ENV_DUP(config, &env_value, + L"PYTHONPROFILEIMPORTTIME", + "PYTHONPROFILEIMPORTTIME"); + if (_PyStatus_EXCEPTION(status)) { + return status; + } + if (env_value != NULL) { + status = config_set_import_time(config, env_value); + PyMem_RawFree(env_value); + return status; + } + + return _PyStatus_OK(); +} static PyStatus config_read_complex_options(PyConfig *config) @@ -2257,17 +2315,18 @@ config_read_complex_options(PyConfig *config) config->faulthandler = 1; } } - if (config_get_env(config, "PYTHONPROFILEIMPORTTIME") - || config_get_xoption(config, L"importtime")) { - config->import_time = 1; - } - if (config_get_env(config, "PYTHONNODEBUGRANGES") || config_get_xoption(config, L"no_debug_ranges")) { config->code_debug_ranges = 0; } PyStatus status; + + status = config_read_import_time(config); + if (_PyStatus_EXCEPTION(status)) { + return status; + } + if (config->tracemalloc < 0) { status = config_init_tracemalloc(config); if (_PyStatus_EXCEPTION(status)) { From b08198010441bb38fd0ad701e1ccc5b68f48f13c Mon Sep 17 00:00:00 2001 From: Adam Turner <9087854+aa-turner@users.noreply.github.com> Date: Sat, 3 May 2025 03:01:14 +0100 Subject: [PATCH 2/6] Print importtime header before first cached import --- Python/import.c | 26 +++++++++++++++----------- 1 file changed, 15 insertions(+), 11 deletions(-) diff --git a/Python/import.c b/Python/import.c index 08d64d0d662d62..afdc28eda31b9b 100644 --- a/Python/import.c +++ b/Python/import.c @@ -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 */ @@ -262,13 +271,14 @@ import_ensure_initialized(PyInterpreterState *interp, PyObject *mod, PyObject *n Py_DECREF(value); done: - /* When -Ximporttime=2, print an import time entry even if an - * imported module has already been loaded. + /* 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) { + 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)); + import_level*2, PyUnicode_AsUTF8(name)); #undef import_level } @@ -3702,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 From ee7a4a0e0d36a31ac0ce5f63710211276de180a2 Mon Sep 17 00:00:00 2001 From: Adam Turner <9087854+aa-turner@users.noreply.github.com> Date: Sat, 3 May 2025 05:38:45 +0100 Subject: [PATCH 3/6] _pyrepl style changes --- Lib/_pyrepl/unix_console.py | 5 ++--- Lib/_pyrepl/windows_console.py | 8 ++++---- 2 files changed, 6 insertions(+), 7 deletions(-) diff --git a/Lib/_pyrepl/unix_console.py b/Lib/_pyrepl/unix_console.py index a6a3c68c92d0f8..2a7a91d0206309 100644 --- a/Lib/_pyrepl/unix_console.py +++ b/Lib/_pyrepl/unix_console.py @@ -42,7 +42,6 @@ # declare posix optional to allow None assignment on other platforms posix: types.ModuleType | None - try: import posix except ImportError: @@ -574,8 +573,8 @@ def clear(self): @property def input_hook(self): - # avoid inline imports here so the repl doesn't get flooded with import - # logging from -Ximporttime=2 + # 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 diff --git a/Lib/_pyrepl/windows_console.py b/Lib/_pyrepl/windows_console.py index efadad629411dd..05611d9c8f2bad 100644 --- a/Lib/_pyrepl/windows_console.py +++ b/Lib/_pyrepl/windows_console.py @@ -59,8 +59,8 @@ 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: @@ -128,7 +128,7 @@ class _error(Exception): def _supports_vt(): try: - nt._supports_virtual_terminal() + return nt._supports_virtual_terminal() except AttributeError: return False @@ -241,8 +241,8 @@ def refresh(self, screen: list[str], c_xy: tuple[int, int]) -> None: @property def input_hook(self): - # avoid inline imports here so the repl doesn't get flooded with import - # logging from -Ximporttime=2 + # 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 From 0226aa171aaf5cad306bb79d9808ca2b54fcbf7a Mon Sep 17 00:00:00 2001 From: Adam Turner <9087854+aa-turner@users.noreply.github.com> Date: Sat, 3 May 2025 05:44:54 +0100 Subject: [PATCH 4/6] Simplify config->import_time initialisation --- Python/initconfig.c | 81 ++++++++++++++++----------------------------- 1 file changed, 29 insertions(+), 52 deletions(-) diff --git a/Python/initconfig.c b/Python/initconfig.c index f12ae75524b3da..ca689547b214c0 100644 --- a/Python/initconfig.c +++ b/Python/initconfig.c @@ -1005,6 +1005,7 @@ _PyConfig_InitCompatConfig(PyConfig *config) memset(config, 0, sizeof(*config)); config->_config_init = (int)_PyConfig_INIT_COMPAT; + config->import_time = -1; config->isolated = -1; config->use_environment = -1; config->dev_mode = -1; @@ -2247,61 +2248,36 @@ config_init_run_presite(PyConfig *config) } #endif -/* Set `config->import_time` based on `value` from `-Ximporttime(=.*)?`. */ static PyStatus -config_set_import_time(PyConfig *config, const wchar_t *value) +config_init_import_time(PyConfig *config) { - int numeric_value; + int importtime = 0; - // If no value is specified or the value is not an integer, use 1. - if (*value == 0 || config_wstr_to_int(value, &numeric_value) != 0) { - config->import_time = 1; - } - - /* -Ximporttime=1 incurs the default behavior. -Ximporttime=2 also - * prints import cache hits. All other numeric values are reserved. - */ - else if (0 <= numeric_value && numeric_value <= 2) { - config->import_time = numeric_value; - } - - else { - return _PyStatus_ERR( - "-X importtime: numeric values other than 1 or 2 are " - "reserved for future use"); - } - - return _PyStatus_OK(); -} - -/* Configure `config->import_time` by checking -Ximporttime then the - * PYTHONPROFILEIMPORTTIME environment variable. Defaults to 0. - */ -static PyStatus -config_read_import_time(PyConfig *config) -{ - /* Check the -X option first. */ - const wchar_t *xoption_value = NULL; - xoption_value = config_get_xoption_value(config, L"importtime"); - if (xoption_value != NULL) { - return config_set_import_time(config, xoption_value); + const char *env = config_get_env(config, "PYTHONPROFILEIMPORTTIME"); + if (env) { + if (_Py_str_to_int(env, &importtime) != 0) { + importtime = 1; + } + if (importtime < 0 || importtime > 2) { + return _PyStatus_ERR( + "PYTHONPROFILEIMPORTTIME: numeric values other than 1 and 2 " + "are reserved for future use."); + } } - /* If there's no -Ximporttime, look for ENV flag */ - wchar_t *env_value = NULL; - /* `CONFIG_GET_ENV_DUP` requires dest to be initialized to `NULL`. */ - PyStatus status = CONFIG_GET_ENV_DUP(config, &env_value, - L"PYTHONPROFILEIMPORTTIME", - "PYTHONPROFILEIMPORTTIME"); - if (_PyStatus_EXCEPTION(status)) { - return status; - } - if (env_value != NULL) { - status = config_set_import_time(config, env_value); - PyMem_RawFree(env_value); - return status; + const wchar_t *x_value = config_get_xoption_value(config, L"importtime"); + if (x_value) { + if (*x_value == 0 || config_wstr_to_int(x_value, &importtime) != 0) { + importtime = 1; + } + if (importtime < 0 || importtime > 2) { + return _PyStatus_ERR( + "-X importtime: values other than 1 and 2 " + "are reserved for future use."); + } } + config->import_time = importtime; return _PyStatus_OK(); } @@ -2321,10 +2297,11 @@ config_read_complex_options(PyConfig *config) } PyStatus status; - - status = config_read_import_time(config); - if (_PyStatus_EXCEPTION(status)) { - return status; + if (config->import_time < 0) { + status = config_init_import_time(config); + if (_PyStatus_EXCEPTION(status)) { + return status; + } } if (config->tracemalloc < 0) { From 0b0c56d75d6d1e7b88e798843ebd44c3532ee045 Mon Sep 17 00:00:00 2001 From: Adam Turner <9087854+aa-turner@users.noreply.github.com> Date: Sat, 3 May 2025 05:39:24 +0100 Subject: [PATCH 5/6] Update tests, add a few more cases --- Lib/test/test_cmd_line.py | 28 ++++++++++++---------------- Lib/test/test_embed.py | 6 +++--- Lib/test/test_support.py | 1 + Programs/_testembed.c | 4 ++-- 4 files changed, 18 insertions(+), 21 deletions(-) diff --git a/Lib/test/test_cmd_line.py b/Lib/test/test_cmd_line.py index 2dda393e7d13d0..1b40e0d05fe3bc 100644 --- a/Lib/test/test_cmd_line.py +++ b/Lib/test/test_cmd_line.py @@ -1159,23 +1159,19 @@ def test_cpu_count_default(self): self.assertEqual(self.res2int(res), (os.cpu_count(), os.process_cpu_count())) def test_import_time(self): - code = "import os" - res = assert_python_ok('-X', 'importtime', '-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") - - code = "import os" - res = assert_python_ok('-X', 'importtime=true', '-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") - - code = "import os; import os" + # 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") + 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) diff --git a/Lib/test/test_embed.py b/Lib/test/test_embed.py index 4e6bf4d243bab7..95b2d80464c349 100644 --- a/Lib/test/test_embed.py +++ b/Lib/test/test_embed.py @@ -998,7 +998,7 @@ def test_init_from_config(self): 'hash_seed': 123, 'tracemalloc': 2, 'perf_profiling': 0, - 'import_time': 0, + 'import_time': 2, 'code_debug_ranges': False, 'show_ref_count': True, 'malloc_stats': True, @@ -1064,7 +1064,7 @@ def test_init_compat_env(self): 'use_hash_seed': True, 'hash_seed': 42, 'tracemalloc': 2, - 'import_time': 0, + 'import_time': 1, 'code_debug_ranges': False, 'malloc_stats': True, 'inspect': True, @@ -1100,7 +1100,7 @@ def test_init_python_env(self): 'use_hash_seed': True, 'hash_seed': 42, 'tracemalloc': 2, - 'import_time': 0, + 'import_time': 1, 'code_debug_ranges': False, 'malloc_stats': True, 'inspect': True, diff --git a/Lib/test/test_support.py b/Lib/test/test_support.py index 468bac82924bb1..8446da03e3645b 100644 --- a/Lib/test/test_support.py +++ b/Lib/test/test_support.py @@ -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'], diff --git a/Programs/_testembed.c b/Programs/_testembed.c index 2d4a271b7fc49e..8a7412c7019e60 100644 --- a/Programs/_testembed.c +++ b/Programs/_testembed.c @@ -651,8 +651,8 @@ static int test_init_from_config(void) putenv("PYTHONTRACEMALLOC=0"); config.tracemalloc = 2; - putenv("PYTHONPROFILEIMPORTTIME=0"); - config.import_time = 0; + putenv("PYTHONPROFILEIMPORTTIME=1"); + config.import_time = 2; putenv("PYTHONNODEBUGRANGES=0"); config.code_debug_ranges = 0; From f9c07ce7d9d5e36d9b974fa8d87d92531b2d2bf9 Mon Sep 17 00:00:00 2001 From: Adam Turner <9087854+aa-turner@users.noreply.github.com> Date: Sat, 3 May 2025 05:39:10 +0100 Subject: [PATCH 6/6] Documentation --- Doc/c-api/init_config.rst | 11 ++++++++--- Doc/using/cmdline.rst | 7 ++++--- Doc/whatsnew/3.14.rst | 10 +++++----- Misc/ACKS | 1 + .../2024-07-11-12-31-29.gh-issue-102567.weRqDn.rst | 1 + Misc/python.man | 11 ++++++++--- Python/initconfig.c | 4 ++-- 7 files changed, 29 insertions(+), 16 deletions(-) diff --git a/Doc/c-api/init_config.rst b/Doc/c-api/init_config.rst index 22a766822b712a..1f413a802c304e 100644 --- a/Doc/c-api/init_config.rst +++ b/Doc/c-api/init_config.rst @@ -363,7 +363,7 @@ Configuration Options - Read-only * - ``"import_time"`` - :c:member:`import_time ` - - ``bool`` + - ``int`` - Read-only * - ``"inspect"`` - :c:member:`inspect ` @@ -1477,14 +1477,19 @@ PyConfig .. c:member:: int import_time - If non-zero, profile import time. If ``2``, include additional output that - indicates when an imported module has already been loaded. + If ``1``, profile import time. + If ``2``, include additional output that indicates + when an imported module has already been loaded. 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. diff --git a/Doc/using/cmdline.rst b/Doc/using/cmdline.rst index ebe178d9729231..19143650f74b39 100644 --- a/Doc/using/cmdline.rst +++ b/Doc/using/cmdline.rst @@ -539,12 +539,13 @@ 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 the self time and cumulative time columns. + ``cached`` will be printed in both time columns. + + See also :envvar:`PYTHONPROFILEIMPORTTIME`. .. versionadded:: 3.7 diff --git a/Doc/whatsnew/3.14.rst b/Doc/whatsnew/3.14.rst index 2f3df4fd36f3b5..94882f565630b1 100644 --- a/Doc/whatsnew/3.14.rst +++ b/Doc/whatsnew/3.14.rst @@ -626,12 +626,12 @@ Other language changes of HMAC is not available. (Contributed by Bénédikt Tran in :gh:`99108`.) -* :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. The ``self`` and ``cumulative`` times for such entries +* 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`` are now reserved for future use. - (Contributed by Noah Kim in :gh:`118655`.) + 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 diff --git a/Misc/ACKS b/Misc/ACKS index 42068ec6aefbd2..610dcf9f4238de 100644 --- a/Misc/ACKS +++ b/Misc/ACKS @@ -966,6 +966,7 @@ Beomsoo Bombs Kim Derek D. Kim Gihwan Kim Jan Kim +Noah Kim Taek Joo Kim Yeojin Kim Sam Kimbrel diff --git a/Misc/NEWS.d/next/Core_and_Builtins/2024-07-11-12-31-29.gh-issue-102567.weRqDn.rst b/Misc/NEWS.d/next/Core_and_Builtins/2024-07-11-12-31-29.gh-issue-102567.weRqDn.rst index 6141a80477aeae..04ebbfa128c289 100644 --- a/Misc/NEWS.d/next/Core_and_Builtins/2024-07-11-12-31-29.gh-issue-102567.weRqDn.rst +++ b/Misc/NEWS.d/next/Core_and_Builtins/2024-07-11-12-31-29.gh-issue-102567.weRqDn.rst @@ -1,3 +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. diff --git a/Misc/python.man b/Misc/python.man index fa88a2586dcabf..15174b62d5fea4 100644 --- a/Misc/python.man +++ b/Misc/python.man @@ -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 @@ -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 diff --git a/Python/initconfig.c b/Python/initconfig.c index ca689547b214c0..e827091172162e 100644 --- a/Python/initconfig.c +++ b/Python/initconfig.c @@ -312,8 +312,8 @@ The following implementation-specific options are available:\n\ "-X gil=[0|1]: enable (1) or disable (0) the GIL; also PYTHON_GIL\n" #endif "\ --X importtime[=2]: show how long each import takes; -X importtime=2 also prints\ - rows for imports of already-loaded modules; also PYTHONPROFILEIMPORTTIME\n\ +-X importtime[=2]: show how long each import takes; use -X importtime=2 to\ + log imports of already-loaded modules; also PYTHONPROFILEIMPORTTIME\n\ -X int_max_str_digits=N: limit the size of int<->str conversions;\n\ 0 disables the limit; also PYTHONINTMAXSTRDIGITS\n\ -X no_debug_ranges: don't include extra location information in code objects;\n\