Add -X importtime=2 for logging an importtime message for already-loa…

…ded modules
python · AA-Turner · May 6, 2025 · May 6, 2024 · May 3, 2025 · May 3, 2025
commit 58d07bec9da1623e5fac34b4658f110d78b28aeb
@@ -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
@@ -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 <devmode>`, 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
 

@@ -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.

@@ -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:

@@ -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()
-        nt._supports_virtual_terminal()
+        return nt._supports_virtual_terminal()
-        nt._supports_virtual_terminal()
+        return 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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;

@@ -246,16 +246,32 @@ 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 -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;
 }
 

@@ -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)) {