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'

Author: methane

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
 ~~~~~~~~~~~~~~~~~~~~~~~~~

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.

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;
  }