bpo-31415: Add `-X importtime` option (GH-3490)

It shows show import time of each module.
It's useful for optimizing startup time.

Typical usage: python -X importtime -c 'import requests'

3 files changed, 51 insertions, 0 deletions

diff --git a/Doc/using/cmdline.rst b/Doc/using/cmdline.rst
index 5adad15..9c1c269 100644
--- a/Doc/using/cmdline.rst
+++ b/Doc/using/cmdline.rst
@@ -407,6 +407,10 @@ Miscellaneous options
    * ``-X showalloccount`` to output the total count of allocated objects for
      each type when the program finishes. This only works when Python was built with
      ``COUNT_ALLOCS`` defined.
+   * ``-X importtime`` to show how long each import takes. It shows module name,
+     cumulative time (including nested imports) and self time (exluding nested
+     imports).  Note that its output may be broken in multi threaded application.
+     Typical usage is ``python3 -X importtime -c 'import asyncio'``.
 
    It also allows passing arbitrary values and retrieving them through the
    :data:`sys._xoptions` dictionary.
@@ -423,6 +427,9 @@ Miscellaneous options
    .. versionadded:: 3.6
       The ``-X showalloccount`` option.
 
+   .. versionadded:: 3.7
+      The ``-X importtime`` option.
+
 
 Options you shouldn't use
 ~~~~~~~~~~~~~~~~~~~~~~~~~
diff --git a/Misc/NEWS.d/next/Core and Builtins/2017-09-11-14-28-56.bpo-31415.GBdz7o.rst b/Misc/NEWS.d/next/Core and Builtins/2017-09-11-14-28-56.bpo-31415.GBdz7o.rst
new file mode 100644
index 0000000..52aa16a
--- /dev/null
+++ b/Misc/NEWS.d/next/Core and Builtins/2017-09-11-14-28-56.bpo-31415.GBdz7o.rst
@@ -0,0 +1,2 @@
+Add ``-X importtime`` option to show how long each import takes. It can
+be used to optimize application's startup time.
diff --git a/Python/import.c b/Python/import.c
index e50ea4d..7554bf8 100644
--- a/Python/import.c
+++ b/Python/import.c
@@ -1667,8 +1667,38 @@ PyImport_ImportModuleLevelObject(PyObject *name, PyObject *globals,
         }
     }
     else {
+        static int ximporttime = 0;
+        static int import_level;
+        static _PyTime_t accumulated;
+        _Py_IDENTIFIER(importtime);
+
+        _PyTime_t t1 = 0, accumulated_copy = accumulated;
+
         Py_XDECREF(mod);
 
+        /* XOptions is initialized after first some imports.
+         * So we can't have negative cache.
+         * Anyway, importlib.__find_and_load is much slower than
+         * _PyDict_GetItemId()
+         */
+        if (ximporttime == 0) {
+            PyObject *xoptions = PySys_GetXOptions();
+            if (xoptions) {
+                PyObject *value = _PyDict_GetItemId(xoptions, &PyId_importtime);
+                ximporttime = (value == Py_True);
+            }
+            if (ximporttime) {
+                fputs("import time: self [us] | cumulative | imported package\n",
+                      stderr);
+            }
+        }
+
+        if (ximporttime) {
+            import_level++;
+            t1 = _PyTime_GetMonotonicClock();
+            accumulated = 0;
+        }
+
         if (PyDTrace_IMPORT_FIND_LOAD_START_ENABLED())
             PyDTrace_IMPORT_FIND_LOAD_START(PyUnicode_AsUTF8(abs_name));
 
@@ -1680,6 +1710,18 @@ PyImport_ImportModuleLevelObject(PyObject *name, PyObject *globals,
             PyDTrace_IMPORT_FIND_LOAD_DONE(PyUnicode_AsUTF8(abs_name),
                                            mod != NULL);
 
+        if (ximporttime) {
+            _PyTime_t cum = _PyTime_GetMonotonicClock() - t1;
+
+            import_level--;
+            fprintf(stderr, "import time: %9ld | %10ld | %*s%s\n",
+                    (long)_PyTime_AsMicroseconds(cum - accumulated, _PyTime_ROUND_CEILING),
+                    (long)_PyTime_AsMicroseconds(cum, _PyTime_ROUND_CEILING),
+                    import_level*2, "", PyUnicode_AsUTF8(abs_name));
+
+            accumulated = accumulated_copy + cum;
+        }
+
         if (mod == NULL) {
             goto error;
         }