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

Co-authored-by: Adam Turner <9087854+aa-turner@users.noreply.github.com>

Doc/c-api/init_config.rst

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

Doc/using/cmdline.rst

@@ -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
+     application.  Typical usage is ``python -X importtime -c 'import asyncio'``.
-     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 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`.
@@ -982,12 +992,17 @@ conflict.
 
 .. envvar:: PYTHONPROFILEIMPORTTIME
 
-   If this environment variable is set to a non-empty string, Python will
+   If this environment variable is set to ``1``, Python will show
-   show how long each import takes.
+   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
 

Doc/whatsnew/3.14.rst

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

Lib/_pyrepl/unix_console.py

@@ -29,6 +29,7 @@ import signal
 import struct
 import termios
 import time
+import types
 import platform
 from fcntl import ioctl
 
@@ -39,6 +40,12 @@ from .trace import trace
 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
 
@@ -556,11 +563,9 @@ class UnixConsole(Console):
 
     @property
     def input_hook(self):
-        try:
+        # avoid inline imports here so the repl doesn't get flooded
-            import posix
+        # with import logging from -X importtime=2
-        except ImportError:
+        if posix is not None and posix._is_inputhook_installed():
-            return None
-        if posix._is_inputhook_installed():
             return posix._inputhook
 
     def __enable_bracketed_paste(self) -> None:

Lib/_pyrepl/windows_console.py

@@ -24,6 +24,7 @@ import os
 import sys
 
 import ctypes
+import types
 from ctypes.wintypes import (
     _COORD,
     WORD,
@@ -58,6 +59,12 @@ except:
             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
 
@@ -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):
@@ -235,11 +241,9 @@ class WindowsConsole(Console):
 
     @property
     def input_hook(self):
-        try:
+        # avoid inline imports here so the repl doesn't get flooded
-            import nt
+        # with import logging from -X importtime=2
-        except ImportError:
+        if nt is not None and nt._is_inputhook_installed():
-            return None
-        if nt._is_inputhook_installed():
             return nt._inputhook
 
     def __write_changed_line(

Lib/test/test_capi/test_config.py

@@ -57,7 +57,7 @@ class CAPITests(unittest.TestCase):
             ("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),

Lib/test/test_cmd_line.py

@@ -1158,6 +1158,24 @@ class CmdLineTest(unittest.TestCase):
         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())

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 @@ class InitConfigTests(EmbeddingTestsMixin, unittest.TestCase):
             '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,
@@ -1064,7 +1064,7 @@ class InitConfigTests(EmbeddingTestsMixin, unittest.TestCase):
             'use_hash_seed': True,
             'hash_seed': 42,
             'tracemalloc': 2,
-            'import_time': True,
+            'import_time': 1,
             'code_debug_ranges': False,
             'malloc_stats': True,
             'inspect': True,
@@ -1100,7 +1100,7 @@ class InitConfigTests(EmbeddingTestsMixin, unittest.TestCase):
             'use_hash_seed': True,
             'hash_seed': 42,
             'tracemalloc': 2,
-            'import_time': True,
+            'import_time': 1,
             'code_debug_ranges': False,
             'malloc_stats': True,
             'inspect': True,

Lib/test/test_support.py

@@ -561,6 +561,7 @@ class TestSupport(unittest.TestCase):
             ['-Wignore', '-X', 'dev'],
             ['-X', 'faulthandler'],
             ['-X', 'importtime'],
+            ['-X', 'importtime=2'],
             ['-X', 'showrefcount'],
             ['-X', 'tracemalloc'],
             ['-X', 'tracemalloc=3'],

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

Misc/NEWS.d/next/Core_and_Builtins/2024-07-11-12-31-29.gh-issue-102567.weRqDn.rst

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

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
+If this environment variable is set to \fB1\fR, Python will show
-show how long each import takes. This is exactly equivalent to setting
+how long each import takes. If set to \fB2\fR, Python will include output for
-\fB\-X importtime\fP on the command line.
+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

Programs/_testembed.c

@@ -651,8 +651,8 @@ static int test_init_from_config(void)
     putenv("PYTHONTRACEMALLOC=0");
     config.tracemalloc = 2;
 
-    putenv("PYTHONPROFILEIMPORTTIME=0");
+    putenv("PYTHONPROFILEIMPORTTIME=1");
-    config.import_time = 1;
+    config.import_time = 2;
 
     putenv("PYTHONNODEBUGRANGES=0");
     config.code_debug_ranges = 0;

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 */
@@ -246,9 +255,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 +269,19 @@ import_ensure_initialized(PyInterpreterState *interp, PyObject *mod, PyObject *n
         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;
 }
 
@@ -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
+        _IMPORT_TIME_HEADER(interp);
-        if (header) {
-            fputs("import time: self [us] | cumulative | imported package\n",
-                  stderr);
-            header = 0;
-        }
-#undef header
 
         import_level++;
         // ignore error: don't block import if reading the clock fails

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; 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\
@@ -1004,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;
@@ -2246,6 +2248,38 @@ config_init_run_presite(PyConfig *config)
 }
 #endif
 
+static PyStatus
+config_init_import_time(PyConfig *config)
+{
+    int importtime = 0;
+
+    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.");
+        }
+    }
+
+    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();
+}
 
 static PyStatus
 config_read_complex_options(PyConfig *config)
@@ -2257,17 +2291,19 @@ 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;
+    if (config->import_time < 0) {
+        status = config_init_import_time(config);
+        if (_PyStatus_EXCEPTION(status)) {
+            return status;
+        }
+    }
+
     if (config->tracemalloc < 0) {
         status = config_init_tracemalloc(config);
         if (_PyStatus_EXCEPTION(status)) {