[WIP] bpo-31415: Add -X importtime option

[vstinner]

XXX PR created to discuss importtime logs format of @methane PR #3490.

https://bugs.python.org/issue31415

[vstinner]

Example:

haypo@selma$ ./python -X importtime -c pass
[0.007768] import time: import encodings
[0.009267] import time:   import codecs
[0.010331] import time:     import _codecs
[0.010565] import time:     import _codecs took 235 us
[0.011226] import time:   import codecs took 1725 us (cumulative: 1960 us)
[0.011294] import time:   import encodings.aliases
[0.012286] import time:   import encodings.aliases took 992 us
[0.012433] import time: import encodings took 1715 us (cumulative: 4666 us)
[0.012487] import time: import encodings.utf_8
[0.013126] import time: import encodings.utf_8 took 640 us
[0.013188] import time: import _signal
[0.013504] import time: import _signal took 317 us
[0.013553] import time: import encodings.latin_1
[0.014288] import time: import encodings.latin_1 took 736 us
[0.014318] import time: import io
[0.014789] import time:   import abc
[0.015366] import time:     import _weakrefset
[0.016324] import time:     import _weakrefset took 958 us
[0.016727] import time:   import abc took 981 us (cumulative: 1939 us)
[0.017637] import time: import io took 1381 us (cumulative: 3320 us)
[0.017888] import time: import site
[0.018758] import time:   import os
[0.019818] import time:     import errno
[0.020151] import time:     import errno took 333 us
[0.020164] import time:     import stat
[0.020890] import time:       import _stat
[0.021161] import time:       import _stat took 271 us
[0.021284] import time:     import stat took 849 us (cumulative: 1120 us)
[0.021471] import time:     import posixpath
[0.022126] import time:       import genericpath
[0.022702] import time:       import genericpath took 576 us
[0.022798] import time:     import posixpath took 752 us (cumulative: 1328 us)
[0.023306] import time:     import _collections_abc
[0.029017] import time:     import _collections_abc took 5712 us
[0.029551] import time:   import os took 2302 us (cumulative: 10793 us)
[0.029584] import time:   import _sitebuiltins
[0.030299] import time:   import _sitebuiltins took 716 us
[0.032091] import time:   import sitecustomize
[0.033053] import time:   import sitecustomize took 962 us
[0.033086] import time:   import usercustomize
[0.033740] import time:   import usercustomize took 654 us
[0.033820] import time: import site took 2811 us (cumulative: 15933 us)

[warsaw]

I really like this format. It's much easier to read and understand.

[methane]

I agree your format is more easy to understand at first glance.
On the other hand, your format doubles number of lines. Increased lines don't provide any information.
But I'm ok to use grep took to filter them out.

FYI, searching slow subtree is the most important use case of this file.
Many editors supports indent level folding. It helps this use case a lot.
Here are screenshots of vim. (all screenshot removed import time: prefix).

My format, replaced - with imported

When I found slow import, unfold folded block above the line.

Your format

Your format, with grep took | tac

[methane]

If {{{ and }}} are added to your format, I can fold subtree without removing prefix.
But I don't know how many other popular editors support Vim's foldmarker.

[methane]

@mattn teach me nice folding script: https://gist.github.com/mattn/253c12d5ca22e06accb18e06b5e4e854

[methane]

Sorry for random posts. My thoughts are:

output size

Minimum format is nice to paste in email, issue tracker or Github.

I can use grep and cut always. But out-of-the box format is still important because
-X importtime is casual profiler for many application / library developers.

easy to use for looking large tree

Support folding is important, because some applications have hundreds of import.

If import modulename is logged just before import, adding some marker (maybe, { and }) may
allow folding in some editors, without removing prefix.

[ncoghlan]

My main question for both this and @methane's original patch would be to ask how it looks when combined with python -v, which prints output like:

# extension module 'readline' loaded from '/usr/lib64/python3.6/lib-dynload/readline.cpython-36m-x86_64-linux-gnu.so'
# extension module 'readline' executed from '/usr/lib64/python3.6/lib-dynload/readline.cpython-36m-x86_64-linux-gnu.so'
import 'readline' # <_frozen_importlib_external.ExtensionFileLoader object at 0x7f9846e63748>
import 'atexit' # <class '_frozen_importlib.BuiltinImporter'>
# /usr/lib64/python3.6/__pycache__/rlcompleter.cpython-36.pyc matches /usr/lib64/python3.6/rlcompleter.py
# code object from '/usr/lib64/python3.6/__pycache__/rlcompleter.cpython-36.pyc'
import 'rlcompleter' # <_frozen_importlib_external.SourceFileLoader object at 0x7f9846e63860>

I'd also ask whether the "starting import" lines in this import nesting version could be updated to:

1. Only get shown for python -v -X importtime (so the default formatting still uses indentation to indicate import chains, but also only reports when an import ends, not when it started)
2. Includes the origin information for the imports

[vstinner]

PR 3490 was merged.