Merge pull request #1 from AA-Turner/3.14-importtime=2

`-X importtime=2` feedback

(Thanks so much, @AA-Turner)

Author: noahbkim

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

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
 

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

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
 

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
 

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)

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,

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'],

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

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

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

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;

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