Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

bpo-31415: Add -X importtime option. #3490

Merged
merged 9 commits into from
Oct 3, 2017
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions Doc/using/cmdline.rst
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hum, maybe rename the option to "-X importime"? I don't know.

Maybe explain that the displayed time is the cumulative time, including import time of sub-imports.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I changed importprofile to importtime.
And self time is shown now, as Serhiy's suggestion.


It also allows passing arbitrary values and retrieving them through the
:data:`sys._xoptions` dictionary.
Expand All @@ -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
~~~~~~~~~~~~~~~~~~~~~~~~~
Expand Down
Original file line number Diff line number Diff line change
@@ -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.
32 changes: 32 additions & 0 deletions Python/import.c
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

_PyTime_t has no unit. You cannot use directly t2-t1.

I suggest you to use _PyTime_AsMicroseconds(t2 - t1, _PyTime_ROUND_CEILING). Moreover, it will round "correctly" ;-) (towards +inf, rather than towards zero).

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

fixed

fprintf(stderr, "%*s- %s %ld [us]\n",
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In your sample, the output looks nice. But imports can emit warnings, importlib can log extrat messages (try python3 -v), etc. It would help parsing to prefix messages. For example: "import_time: (...)."

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Updated format, and output example in pull request comment.

import_level*2, "",
PyUnicode_AsUTF8(abs_name),
(long)(t2 - t1) / 1000);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would it be possible to use the ms unit if us >= 10 000? It would make the output easier to read, no?

I don't understand the "123 [us]" format. Why not "123 us"?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would vote for "123 us" too, or "[123 us]".

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Square brackets is used to make it clear it's not variable (123 * u * s), but physical unit (123 in μs).
In English, it's rarely used, only when it can be confusing.

In Japan, some community use "use square bracket always for physical unit" habit.
And I studied in such college.
I just know it's local habit and abuse in general!

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would it be possible to use the ms unit if us >= 10 000? It would make the output easier to read, no?

I prefer fixed unit. It makes post analysis (e.g. generate Flame Graph) easy.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agreed with @methane. Mixed units are confusing when values are meant to be compared.

}

if (mod == NULL) {
goto error;
}
Expand Down