From 280d5859855d7858233816d10fedb414ac725f1d Mon Sep 17 00:00:00 2001 From: INADA Naoki Date: Mon, 11 Sep 2017 14:31:02 +0900 Subject: [PATCH 1/8] bpo-31415: Add ``-X importprofile`` option. It shows show import time of each module. It's useful for optimizing startup time. --- Doc/using/cmdline.rst | 5 +++ .../2017-09-11-14-28-56.bpo-31415.GBdz7o.rst | 2 ++ Python/import.c | 32 +++++++++++++++++++ 3 files changed, 39 insertions(+) create mode 100644 Misc/NEWS.d/next/Core and Builtins/2017-09-11-14-28-56.bpo-31415.GBdz7o.rst diff --git a/Doc/using/cmdline.rst b/Doc/using/cmdline.rst index 5adad159e65cc1..370850fb21557b 100644 --- a/Doc/using/cmdline.rst +++ b/Doc/using/cmdline.rst @@ -407,6 +407,8 @@ 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 importprofile`` to show how long each import takes. Nested imports are + indented. It can be used to optimize application's startup time. It also allows passing arbitrary values and retrieving them through the :data:`sys._xoptions` dictionary. @@ -423,6 +425,9 @@ Miscellaneous options .. versionadded:: 3.6 The ``-X showalloccount`` option. + .. versionadded:: 3.7 + The ``-X importprofile`` 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..e2f966b26c19e7 --- /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 importprofile`` 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..ef0221abcfc599 100644 --- a/Python/import.c +++ b/Python/import.c @@ -1666,10 +1666,42 @@ PyImport_ImportModuleLevelObject(PyObject *name, PyObject *globals, } } else { + static int import_level; + _Py_IDENTIFIER(importprofile); + int import_profile = 0; + _PyTime_t t1=0, t2; + 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() + */ + PyObject *xoptions = PySys_GetXOptions(); + if (xoptions) { + PyObject *value = _PyDict_GetItemId(xoptions, &PyId_importprofile); + import_profile = (value == Py_True); + } + + if (import_profile) { + import_level++; + t1 = _PyTime_GetMonotonicClock(); + } + mod = _PyObject_CallMethodIdObjArgs(interp->importlib, &PyId__find_and_load, abs_name, interp->import_func, NULL); + + if (import_profile) { + import_level--; + t2 = _PyTime_GetMonotonicClock(); + fprintf(stderr, "%*s- %s %ld [us]\n", + import_level*2, "", + PyUnicode_AsUTF8(abs_name), + (long)(t2 - t1) / 1000); + } + if (mod == NULL) { goto error; } From cd1f9a6c9fec6a1f921078f5b01ad8bd356d95a4 Mon Sep 17 00:00:00 2001 From: INADA Naoki Date: Mon, 25 Sep 2017 02:34:40 +0900 Subject: [PATCH 2/8] s/importprofile/importtime/ --- Doc/using/cmdline.rst | 4 +++- Python/import.c | 16 ++++++++-------- 2 files changed, 11 insertions(+), 9 deletions(-) diff --git a/Doc/using/cmdline.rst b/Doc/using/cmdline.rst index 370850fb21557b..18d13802255a52 100644 --- a/Doc/using/cmdline.rst +++ b/Doc/using/cmdline.rst @@ -407,8 +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 importprofile`` to show how long each import takes. Nested imports are + * ``-X importtime`` to show how long each import takes. Nested imports are indented. It can be used to optimize application's startup time. + Note that it's 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. diff --git a/Python/import.c b/Python/import.c index ef0221abcfc599..7a797565b93cb8 100644 --- a/Python/import.c +++ b/Python/import.c @@ -1667,8 +1667,8 @@ PyImport_ImportModuleLevelObject(PyObject *name, PyObject *globals, } else { static int import_level; - _Py_IDENTIFIER(importprofile); - int import_profile = 0; + _Py_IDENTIFIER(importtime); + int ximporttime = 0; _PyTime_t t1=0, t2; Py_XDECREF(mod); @@ -1680,11 +1680,11 @@ PyImport_ImportModuleLevelObject(PyObject *name, PyObject *globals, */ PyObject *xoptions = PySys_GetXOptions(); if (xoptions) { - PyObject *value = _PyDict_GetItemId(xoptions, &PyId_importprofile); - import_profile = (value == Py_True); + PyObject *value = _PyDict_GetItemId(xoptions, &PyId_importtime); + ximporttime = (value == Py_True); } - if (import_profile) { + if (ximporttime) { import_level++; t1 = _PyTime_GetMonotonicClock(); } @@ -1693,13 +1693,13 @@ PyImport_ImportModuleLevelObject(PyObject *name, PyObject *globals, &PyId__find_and_load, abs_name, interp->import_func, NULL); - if (import_profile) { + if (ximporttime) { import_level--; t2 = _PyTime_GetMonotonicClock(); - fprintf(stderr, "%*s- %s %ld [us]\n", + fprintf(stderr, "import time: %*s- %s %ld us\n", import_level*2, "", PyUnicode_AsUTF8(abs_name), - (long)(t2 - t1) / 1000); + (long)_PyTime_AsMicroseconds(t2-t1, _PyTime_ROUND_CEILING)); } if (mod == NULL) { From bb03fc36389d772e078c62839d3f642c47b2e05d Mon Sep 17 00:00:00 2001 From: INADA Naoki Date: Mon, 25 Sep 2017 03:04:55 +0900 Subject: [PATCH 3/8] Add 'self' import time. --- Python/import.c | 17 +++++++++++++---- 1 file changed, 13 insertions(+), 4 deletions(-) diff --git a/Python/import.c b/Python/import.c index 7a797565b93cb8..915d0edee6825e 100644 --- a/Python/import.c +++ b/Python/import.c @@ -1667,9 +1667,10 @@ PyImport_ImportModuleLevelObject(PyObject *name, PyObject *globals, } else { static int import_level; + static _PyTime_t accumulated; _Py_IDENTIFIER(importtime); int ximporttime = 0; - _PyTime_t t1=0, t2; + _PyTime_t t1=0, accumulated_copy; Py_XDECREF(mod); @@ -1687,6 +1688,8 @@ PyImport_ImportModuleLevelObject(PyObject *name, PyObject *globals, if (ximporttime) { import_level++; t1 = _PyTime_GetMonotonicClock(); + accumulated_copy = accumulated; + accumulated = 0; } mod = _PyObject_CallMethodIdObjArgs(interp->importlib, @@ -1694,12 +1697,18 @@ PyImport_ImportModuleLevelObject(PyObject *name, PyObject *globals, interp->import_func, NULL); if (ximporttime) { + _PyTime_t t2 = _PyTime_GetMonotonicClock(); + long cum = t2 - t1; + import_level--; - t2 = _PyTime_GetMonotonicClock(); - fprintf(stderr, "import time: %*s- %s %ld us\n", + fprintf(stderr, "import time: %*s- %s %ld us (self %ld us)\n", import_level*2, "", PyUnicode_AsUTF8(abs_name), - (long)_PyTime_AsMicroseconds(t2-t1, _PyTime_ROUND_CEILING)); + (long)_PyTime_AsMicroseconds(cum, _PyTime_ROUND_CEILING), + (long)_PyTime_AsMicroseconds(cum-accumulated, + _PyTime_ROUND_CEILING)); + + accumulated = accumulated_copy + cum; } if (mod == NULL) { From 08cd26f051c7be6714c432aa48edb1d63725b2b0 Mon Sep 17 00:00:00 2001 From: INADA Naoki Date: Mon, 25 Sep 2017 03:31:54 +0900 Subject: [PATCH 4/8] fix typo --- Doc/using/cmdline.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Doc/using/cmdline.rst b/Doc/using/cmdline.rst index 18d13802255a52..aba4be4efee5cb 100644 --- a/Doc/using/cmdline.rst +++ b/Doc/using/cmdline.rst @@ -409,7 +409,7 @@ Miscellaneous options ``COUNT_ALLOCS`` defined. * ``-X importtime`` to show how long each import takes. Nested imports are indented. It can be used to optimize application's startup time. - Note that it's output may be broken in multi threaded application. + 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 From 62019f78917920626726b3cd6fd81b95ddca4dc9 Mon Sep 17 00:00:00 2001 From: INADA Naoki Date: Mon, 25 Sep 2017 03:42:48 +0900 Subject: [PATCH 5/8] Add note about cumulative time and self time. --- Doc/using/cmdline.rst | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/Doc/using/cmdline.rst b/Doc/using/cmdline.rst index aba4be4efee5cb..c93d6087f27a4f 100644 --- a/Doc/using/cmdline.rst +++ b/Doc/using/cmdline.rst @@ -407,8 +407,9 @@ 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. Nested imports are - indented. It can be used to optimize application's startup time. + * ``-X importtime`` to show how long each import takes. It can be used to + optimize application's startup time. Cumulative time (including nested + imports) and self time (exluding nested imports) are shown. Note that its output may be broken in multi threaded application. Typical usage is ``python3 -X importtime -c 'import asyncio'`. From c915ef0f9b19d61942f8055b99d2dec281bc9230 Mon Sep 17 00:00:00 2001 From: INADA Naoki Date: Mon, 25 Sep 2017 03:45:18 +0900 Subject: [PATCH 6/8] Update NEWS --- Doc/using/cmdline.rst | 2 +- .../Core and Builtins/2017-09-11-14-28-56.bpo-31415.GBdz7o.rst | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/Doc/using/cmdline.rst b/Doc/using/cmdline.rst index c93d6087f27a4f..816fddd119b5ce 100644 --- a/Doc/using/cmdline.rst +++ b/Doc/using/cmdline.rst @@ -429,7 +429,7 @@ Miscellaneous options The ``-X showalloccount`` option. .. versionadded:: 3.7 - The ``-X importprofile`` option. + 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 index e2f966b26c19e7..52aa16a972be03 100644 --- 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 @@ -1,2 +1,2 @@ -Add ``-X importprofile`` option to show how long each import takes. It can +Add ``-X importtime`` option to show how long each import takes. It can be used to optimize application's startup time. From 853c0f693cebae1acc7afcb955f7854ce3053c62 Mon Sep 17 00:00:00 2001 From: INADA Naoki Date: Tue, 26 Sep 2017 08:15:47 +0900 Subject: [PATCH 7/8] Fix suspicious check --- Doc/using/cmdline.rst | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/Doc/using/cmdline.rst b/Doc/using/cmdline.rst index 816fddd119b5ce..9c1c269d1dffb9 100644 --- a/Doc/using/cmdline.rst +++ b/Doc/using/cmdline.rst @@ -407,11 +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 can be used to - optimize application's startup time. Cumulative time (including nested - imports) and self time (exluding nested imports) are shown. - Note that its output may be broken in multi threaded application. - Typical usage is ``python3 -X importtime -c 'import asyncio'`. + * ``-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. From 4a2f121eeb2b0e1e25dc839691aaebbc9912d39a Mon Sep 17 00:00:00 2001 From: INADA Naoki Date: Sun, 1 Oct 2017 20:35:53 +0900 Subject: [PATCH 8/8] table format --- Python/import.c | 31 +++++++++++++++++-------------- 1 file changed, 17 insertions(+), 14 deletions(-) diff --git a/Python/import.c b/Python/import.c index eeaf0d83d9395c..7554bf8627225b 100644 --- a/Python/import.c +++ b/Python/import.c @@ -1667,11 +1667,12 @@ PyImport_ImportModuleLevelObject(PyObject *name, PyObject *globals, } } else { + static int ximporttime = 0; static int import_level; static _PyTime_t accumulated; _Py_IDENTIFIER(importtime); - int ximporttime = 0; - _PyTime_t t1=0, accumulated_copy; + + _PyTime_t t1 = 0, accumulated_copy = accumulated; Py_XDECREF(mod); @@ -1680,16 +1681,21 @@ PyImport_ImportModuleLevelObject(PyObject *name, PyObject *globals, * Anyway, importlib.__find_and_load is much slower than * _PyDict_GetItemId() */ - PyObject *xoptions = PySys_GetXOptions(); - if (xoptions) { - PyObject *value = _PyDict_GetItemId(xoptions, &PyId_importtime); - ximporttime = (value == Py_True); + 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_copy = accumulated; accumulated = 0; } @@ -1705,16 +1711,13 @@ PyImport_ImportModuleLevelObject(PyObject *name, PyObject *globals, mod != NULL); if (ximporttime) { - _PyTime_t t2 = _PyTime_GetMonotonicClock(); - long cum = t2 - t1; + _PyTime_t cum = _PyTime_GetMonotonicClock() - t1; import_level--; - fprintf(stderr, "import time: %*s- %s %ld us (self %ld us)\n", - import_level*2, "", - PyUnicode_AsUTF8(abs_name), + fprintf(stderr, "import time: %9ld | %10ld | %*s%s\n", + (long)_PyTime_AsMicroseconds(cum - accumulated, _PyTime_ROUND_CEILING), (long)_PyTime_AsMicroseconds(cum, _PyTime_ROUND_CEILING), - (long)_PyTime_AsMicroseconds(cum-accumulated, - _PyTime_ROUND_CEILING)); + import_level*2, "", PyUnicode_AsUTF8(abs_name)); accumulated = accumulated_copy + cum; }