Add -X importtime=2 for logging an importtime message for already-loaded modules

Author: noahbkim

Doc/c-api/init_config.rst

@@ -1475,9 +1475,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``.

Doc/using/cmdline.rst

@@ -539,8 +539,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`.
@@ -981,12 +990,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
 

Doc/whatsnew/3.14.rst

@@ -463,6 +463,13 @@ Other language changes
   This implementation is used as a fallback when the OpenSSL implementation
   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`.)
 
 
 .. _whatsnew314-pep765:

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:

Lib/test/test_capi/test_config.py

@@ -56,7 +56,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),

Lib/test/test_cmd_line.py

@@ -1067,6 +1067,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())

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,

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.

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;

Python/import.c

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