diff --git a/Doc/using/cmdline.rst b/Doc/using/cmdline.rst index 5adad159e65cc1..9c1c269d1dffb9 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 00000000000000..52aa16a972be03 --- /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 5e841ca782d2bc..0083dd45085c03 100644 --- a/Python/import.c +++ b/Python/import.c @@ -32,6 +32,8 @@ struct _inittab *PyImport_Inittab = _PyImport_Inittab; static PyObject *initstr = NULL; +static _PyTime_t import_start_time; + /*[clinic input] module _imp [clinic start generated code]*/ @@ -41,10 +43,36 @@ module _imp /* Initialize things */ +static int +import_xoptions_importtime(void) +{ + int has_key; + + PyObject *xoptions = PySys_GetXOptions(); + if (xoptions == NULL) { + return -1; + } + + PyObject *key = PyUnicode_FromString("importtime"); + if (key == NULL) { + return -1; + } + + has_key = PyDict_Contains(xoptions, key); + Py_DECREF(key); + if (has_key < 0) { + return -1; + } + return has_key; +} + void _PyImport_Init(void) { PyInterpreterState *interp = PyThreadState_Get()->interp; + + import_start_time = _PyTime_GetMonotonicClock(); + initstr = PyUnicode_InternFromString("__init__"); if (initstr == NULL) Py_FatalError("Can't initialize import variables"); @@ -1666,10 +1694,70 @@ PyImport_ImportModuleLevelObject(PyObject *name, PyObject *globals, } } else { + static int import_level; + static _PyTime_t accumulated = 0; + _PyTime_t t1 = 0, accumulated_copy; + int log_import_time; + + { + int importtime = import_xoptions_importtime(); + if (importtime < 0) { + Py_FatalError("import_xoptions_importtime() failed"); + } + log_import_time = importtime; + } + Py_XDECREF(mod); + + if (log_import_time) { + t1 = _PyTime_GetMonotonicClock(); + accumulated_copy = accumulated; + accumulated = 0; + + time_t ts_sec; + int ts_usec; + (void)_PyTime_AsTimevalTime_t(t1 - import_start_time, + &ts_sec, &ts_usec, + _PyTime_ROUND_CEILING); + + fprintf(stderr, "[%li.%06i] import time: %*simport %s\n", + (long)ts_sec, ts_usec, + import_level*2, "", PyUnicode_AsUTF8(abs_name)); + + import_level++; + } + mod = _PyObject_CallMethodIdObjArgs(interp->importlib, &PyId__find_and_load, abs_name, interp->import_func, NULL); + + if (log_import_time) { + _PyTime_t t2 = _PyTime_GetMonotonicClock(); + _PyTime_t cum = t2 - t1; + _PyTime_t tself, tcum; + time_t ts_sec; + int ts_usec; + + (void)_PyTime_AsTimevalTime_t(t2 - import_start_time, + &ts_sec, &ts_usec, + _PyTime_ROUND_CEILING); + tcum = _PyTime_AsMicroseconds(cum, _PyTime_ROUND_CEILING); + tself = _PyTime_AsMicroseconds(cum - accumulated, + _PyTime_ROUND_CEILING); + + import_level--; + fprintf(stderr, "[%li.%06i] import time: %*simport %s took %lu us", + (long)ts_sec, ts_usec, + import_level*2, "", PyUnicode_AsUTF8(abs_name), + (unsigned long)tself); + if (tcum != tself) { + fprintf(stderr, " (cumulative: %lu us)", (unsigned long)tcum); + } + fprintf(stderr, "\n"); + + accumulated = accumulated_copy + cum; + } + if (mod == NULL) { goto error; }