classification
Title: Add -X option to show import time
Type: enhancement Stage: resolved
Components: Interpreter Core Versions: Python 3.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: gvanrossum Nosy List: brett.cannon, christian.heimes, gvanrossum, haypo, inada.naoki, lukasz.langa, rhettinger, serhiy.storchaka, terry.reedy
Priority: normal Keywords: patch

Created on 2017-09-11 05:27 by inada.naoki, last changed 2017-10-12 15:53 by haypo. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 3490 merged inada.naoki, 2017-09-11 05:37
PR 3765 closed haypo, 2017-09-26 12:57
PR 3936 merged haypo, 2017-10-09 16:44
PR 3942 closed haypo, 2017-10-10 12:35
PR 3955 merged haypo, 2017-10-11 14:51
Messages (26)
msg301858 - (view) Author: INADA Naoki (inada.naoki) * (Python committer) Date: 2017-09-11 05:27
I used my local patch to profile import time.  I think it's useful for
3rd party authors.
For example:

./python -Ximportprofile -c 'import traceback'
    - _codecs 71 [us]
  - codecs 677 [us]
  - encodings.aliases 412 [us]
- encodings 1688 [us]
- encodings.utf_8 250 [us]
- _signal 120 [us]
- encodings.latin_1 281 [us]
    - _weakrefset 301 [us]
  - abc 593 [us]
- io 1032 [us]
  - _locale 100 [us]
- _bootlocale 262 [us]
    - errno 165 [us]
      - _stat 73 [us]
    - stat 270 [us]
      - genericpath 166 [us]
    - posixpath 456 [us]
    - _collections_abc 1798 [us]
  - os 3366 [us]
  - _sitebuiltins 221 [us]
  - sitecustomize 408 [us]
  - usercustomize 168 [us]
- site 5019 [us]
      - _operator 104 [us]
    - operator 873 [us]
    - keyword 177 [us]
      - _heapq 188 [us]
    - heapq 399 [us]
    - itertools 140 [us]
    - reprlib 224 [us]
    - _collections 89 [us]
  - collections 3009 [us]
      - _functools 76 [us]
        - collections.abc 267 [us]
      - types 592 [us]
      - weakref 499 [us]
    - functools 1726 [us]
        - enum 894 [us]
          - _sre 97 [us]
            - sre_constants 428 [us]
          - sre_parse 849 [us]
        - sre_compile 1267 [us]
        - copyreg 200 [us]
      - re 3035 [us]
      - token 222 [us]
    - tokenize 4660 [us]
  - linecache 6592 [us]
- traceback 10108 [us]
msg302556 - (view) Author: Brett Cannon (brett.cannon) * (Python committer) Date: 2017-09-19 18:35
What does the "[us]" mean?
msg302557 - (view) Author: INADA Naoki (inada.naoki) * (Python committer) Date: 2017-09-19 18:39
It means μs (micro seconds), in ASCII.

On 2017年9月20日(水) 3:35 Brett Cannon <report@bugs.python.org> wrote:

>
> Brett Cannon added the comment:
>
> What does the "[us]" mean?
>
> ----------
> nosy: +brett.cannon
>
> _______________________________________
> Python tracker <report@bugs.python.org>
> <https://bugs.python.org/issue31415>
> _______________________________________
>
-- 
Inada Naoki <songofacandy@gmail.com>
msg302559 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-09-19 19:04
If this proposition be accepted I would want to see not only cumulated times, but also pure times, without time of nested imports.

I guess this feature doesn't work correctly with threading.
msg302659 - (view) Author: Brett Cannon (brett.cannon) * (Python committer) Date: 2017-09-20 20:49
Ah, OK. Then I wouldn't put it in square brackets as it seems to suggest it's somehow disconnected from the number.
msg302839 - (view) Author: INADA Naoki (inada.naoki) * (Python committer) Date: 2017-09-24 09:19
> If this proposition be accepted I would want to see not only cumulated times, but also pure times, without time of nested imports.

It can be calculated by script.
I don't want to add more complexity to import.c.

> I guess this feature doesn't work correctly with threading.

Yes, it should be documented.
And that's reason why I don't want to support time without nested import.
Stack management is difficult than inc/dec integer in multi threading case.
msg302842 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-09-24 10:00
> Stack management is difficult than inc/dec integer in multi threading case.

Actually it is easy. You need just one global integer accumulator and a local variable for keeping a temporary copy of it.
msg302875 - (view) Author: INADA Naoki (inada.naoki) * (Python committer) Date: 2017-09-24 18:08
> Actually it is easy. You need just one global integer accumulator and a local variable for keeping a temporary copy of it.

You're right!  I updated my pull request.
See current output: https://gist.github.com/methane/185d75a3c8da762d85317dd95918a623
msg302882 - (view) Author: Raymond Hettinger (rhettinger) * (Python committer) Date: 2017-09-24 19:30
Guido, is this something you want?

Historically, we've shown a lot of restraint when it comes to adding command-line options.  

Also, I'm not sure we want to induce people to start moving their imports inside function calls.  Just because we sometimes adopt constipated programming practices in the standard library doesn't mean we think everyone should do it.  (This is doubly true because sometimes the savings is a false savings if the import eventually occurs downstream and because there is currently work being done on lazy imports that would make the technique irrelevant).
msg302889 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2017-09-24 22:25
@rhettinger
> Guido, is this something you want?

I think it is useful given how much debate there has been around startup time in various contexts (not just pure interpreter startup time but also startup time when using specific libraries, packages or applications).

> Historically, we've shown a lot of restraint when it comes to adding
> command-line options.

But this is hardly a new command-line option; -X already exists. I think it's reasonable to add it here.

> Also, I'm not sure we want to induce people to start moving their imports
> inside function calls. [...]

That's a big leap from collecting the data to suggesting a specific solution. I don't think that making it harder to get the data really is the right approach to discouraging a debatable practice (plus, there are many situations where the practice *is* useful -- just as there are many situations where it's counterproductive). Consenting adults.
msg302895 - (view) Author: Raymond Hettinger (rhettinger) * (Python committer) Date: 2017-09-25 00:04
Naoki, is it possible to separate out how much of this is I/O vs CPU time?

If the I/O dominates, optimizations tend toward zipimports, faster drives, disk caching etc.  If the CPU time is dominant, different techniques are used (lazy evaluation, splitting-out parts of a package, etc).
msg302906 - (view) Author: INADA Naoki (inada.naoki) * (Python committer) Date: 2017-09-25 02:23
I don't have any good idea for it.

I usually run `python -X importtime -c 'import functools'` several times to ensure pyc files are created and it is cached by OS.

On Linux, `strace -c` and `time` command can be used.
But I don't know cross platform way to do it.

$ strace -c python -c 'import asyncio'
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0       244           read
  0.00    0.000000           0       160         2 open
  0.00    0.000000           0       161           close
  0.00    0.000000           0       527        46 stat
  0.00    0.000000           0       266           fstat
  0.00    0.000000           0        16           lstat
  0.00    0.000000           0       114         6 lseek
  0.00    0.000000           0       109           mmap

$ /usr/bin/time python -c 'import asyncio'
0.12user 0.00system 0:00.13elapsed 98%CPU (0avgtext+0avgdata 17004maxresident)k
0inputs+0outputs (0major+2613minor)pagefaults 0swaps
msg302943 - (view) Author: Christian Heimes (christian.heimes) * (Python committer) Date: 2017-09-25 10:39
+1 for an option to profile import time.

I have a minor complain: The output format is not machine-friendly, which makes it harder to perform automatic analysis. I created #31574 / PR3749 to add dtrace probes.
msg302992 - (view) Author: INADA Naoki (inada.naoki) * (Python committer) Date: 2017-09-25 23:35
how can I make it more machine readable?

On 2017年9月25日(月) 19:39 Christian Heimes <report@bugs.python.org> wrote:

>
> Christian Heimes added the comment:
>
> +1 for an option to profile import time.
>
> I have a minor complain: The output format is not machine-friendly, which
> makes it harder to perform automatic analysis. I created #31574 / PR3749 to
> add dtrace probes.
>
> ----------
> nosy: +christian.heimes
>
> _______________________________________
> Python tracker <report@bugs.python.org>
> <https://bugs.python.org/issue31415>
> _______________________________________
>
-- 
Inada Naoki <songofacandy@gmail.com>
msg303038 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-09-26 13:10
The output in PR 3765 partially duplicates the output of the -v option.
msg303039 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-09-26 13:15
> The output in PR 3765 partially duplicates the output of the -v option.

Right. But the idea is to be able to use "grep 'import time:'" to only extract importtime logs. "-v" logs different kind of informations.
msg303568 - (view) Author: Łukasz Langa (lukasz.langa) * (Python committer) Date: 2017-10-02 23:12
Related: https://bugs.python.org/issue31574
msg303593 - (view) Author: INADA Naoki (inada.naoki) * (Python committer) Date: 2017-10-03 10:46
New changeset 1a87de7fcfa3c19f08e29047337c350b4a32b259 by INADA Naoki in branch 'master':
bpo-31415: Add `-X importtime` option (GH-3490)
https://github.com/python/cpython/commit/1a87de7fcfa3c19f08e29047337c350b4a32b259
msg303600 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-03 12:11
Thank you Naoki for this nice enhancement! Tooling always help to take smart decisions on optimizations.
msg303628 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2017-10-03 16:37
This is pretty useless on Windows because you are using a clock with 15-16 milli (not micro) second resolution on Windows.  Before Victor introduced time.perf_counter, with decent behavior on all systems, timeit used different time module functions on Windows and *nix because the two different functions had such different behavior on the two systems.  I believe it used time.clock on Windows (1 second resolution of *nix?) and time.time otherwise (.016 sec resolution on Windows).  

Time.monotonic seems to be based on time.time as it has the same low resolution on Windows.  Run something like

for i in range(1000): time.monotonic()

and you will see identical times except for 1 or 2 jumps of .016.  So the C equivalent or time.clock or time.perf_counter is needed on Windows.  Victor can advise as he knows this better than me.

An example of nearly useless output, with 15-16 millisecond resolution.

f:\dev\3x>python -X importtime -c "import idlelib.pyshell"
Running Debug|Win32 interpreter...
import time: self [us] | cumulative | imported package
import time:         0 |          0 |     _codecs
import time:         0 |          0 |   codecs
import time:         0 |          0 |   encodings.aliases
import time:     15000 |      15000 | encodings
import time:         0 |          0 | encodings.utf_8
import time:         0 |          0 | _signal
import time:         0 |          0 | encodings.latin_1
import time:         0 |          0 |     _weakrefset
import time:         0 |          0 |   abc
import time:         0 |          0 | io
import time:         0 |          0 |       _stat
import time:         0 |          0 |     stat
import time:         0 |          0 |       genericpath
import time:         0 |          0 |     ntpath
import time:         0 |          0 |     _collections_abc
import time:     16000 |      16000 |   os
import time:         0 |          0 |   _sitebuiltins
import time:         0 |          0 |   sitecustomize
import time:         0 |          0 |   usercustomize
import time:     16000 |      32000 | site
import time:         0 |          0 |   idlelib
import time:         0 |          0 |       types
import time:         0 |          0 |       _collections
import time:         0 |          0 |     enum
import time:     16000 |      16000 |     _tkinter
import time:         0 |          0 |     tkinter.constants
import time:         0 |          0 |         _sre
import time:         0 |          0 |           sre_constants
import time:         0 |          0 |         sre_parse
import time:         0 |          0 |       sre_compile
import time:         0 |          0 |         _functools
import time:         0 |          0 |             _operator
import time:         0 |          0 |           operator
import time:         0 |          0 |           keyword
import time:         0 |          0 |             _heapq
import time:         0 |          0 |           heapq
import time:         0 |          0 |           itertools
import time:     15000 |      15000 |           reprlib
import time:         0 |      15000 |         collections
import time:         0 |      15000 |       functools
import time:         0 |          0 |       _locale
import time:         0 |          0 |       copyreg
import time:     16000 |      31000 |     re
import time:         0 |      47000 |   tkinter
import time:         0 |          0 |     tkinter.commondialog
import time:     16000 |      16000 |   tkinter.messagebox
import time:         0 |          0 |           token
import time:         0 |          0 |         tokenize
import time:         0 |          0 |       linecache
import time:         0 |          0 |     traceback
import time:     15000 |      15000 |       __future__
import time:         0 |      15000 |     codeop
import time:         0 |      15000 |   code
import time:         0 |          0 |       time
import time:         0 |          0 |       signal
import time:         0 |          0 |       warnings
import time:         0 |          0 |       errno
import time:         0 |          0 |       threading
import time:         0 |          0 |       msvcrt
import time:         0 |          0 |       _winapi
import time:     16000 |      16000 |     subprocess
import time:     16000 |      32000 |   platform
import time:         0 |          0 |     _socket
import time:         0 |          0 |       collections.abc
import time:         0 |          0 |       math
import time:         0 |          0 |       select
import time:         0 |          0 |     selectors
import time:     15000 |      15000 |   socket
import time:     16000 |      16000 |       configparser
import time:         0 |          0 |       tkinter.font
import time:         0 |          0 |       _bootlocale
import time:         0 |          0 |       encodings.cp1252
import time:     31000 |      47000 |     idlelib.config
import time:         0 |          0 |     idlelib.delegator
import time:     63000 |     110000 |   idlelib.colorizer
import time:         0 |          0 |         posixpath
import time:         0 |          0 |       fnmatch
import time:         0 |          0 |           _ast
import time:     15000 |      15000 |         ast
import time:         0 |          0 |             _opcode
import time:         0 |          0 |           opcode
import time:         0 |          0 |         dis
import time:     16000 |      16000 |           importlib
import time:         0 |      16000 |         importlib.machinery
import time:         0 |      31000 |       inspect
import time:         0 |      31000 |     bdb
import time:         0 |          0 |     tkinter.ttk
import time:         0 |          0 |     idlelib.macosx
import time:         0 |          0 |     idlelib.scrolledlist
import time:         0 |          0 |     idlelib.windows
import time:         0 |      31000 |   idlelib.debugger
import time:     16000 |      16000 |   idlelib.debugger_r
import time:         0 |          0 |     importlib.abc
import time:         0 |          0 |       contextlib
import time:         0 |          0 |     importlib.util
import time:         0 |          0 |       _string
import time:     15000 |      15000 |     string
import time:         0 |          0 |       shlex
import time:         0 |          0 |         zlib
import time:         0 |          0 |           _compression
import time:         0 |          0 |           _bz2
import time:     16000 |      16000 |         bz2
import time:         0 |          0 |           _lzma
import time:         0 |          0 |         lzma
import time:         0 |          0 |         pwd
import time:         0 |          0 |         grp
import time:         0 |      16000 |       shutil
import time:         0 |      16000 |     webbrowser
import time:     15000 |      15000 |     tkinter.simpledialog
import time:         0 |          0 |       tkinter.colorchooser
import time:         0 |          0 |       idlelib.config_key
import time:         0 |          0 |           weakref
import time:         0 |          0 |               org
import time:         0 |          0 |             org.python
import time:         0 |          0 |           org.python.core
import time:         0 |          0 |         copy
import time:         0 |          0 |       idlelib.dynoption
import time:         0 |          0 |           tkinter.dialog
import time:     16000 |      16000 |         tkinter.filedialog
import time:         0 |      16000 |       idlelib.query
import time:         0 |          0 |       idlelib.tabbedpages
import time:         0 |          0 |       idlelib.textview
import time:         0 |          0 |           idlelib.multicall
import time:         0 |          0 |         idlelib.autocomplete_w
import time:         0 |          0 |           idlelib.pyparse
import time:     16000 |      16000 |         idlelib.hyperparser
import time:     15000 |      31000 |       idlelib.autocomplete
import time:         0 |          0 |       idlelib.codecontext
import time:         0 |          0 |       idlelib.parenmatch
import time:         0 |          0 |       idlelib.paragraph
import time:         0 |      47000 |     idlelib.configdialog
import time:         0 |          0 |       idlelib.searchbase
import time:         0 |          0 |       idlelib.searchengine
import time:         0 |          0 |     idlelib.grep
import time:     16000 |      16000 |           html.entities
import time:         0 |      16000 |         html
import time:         0 |          0 |         _markupbase
import time:     16000 |      32000 |       html.parser
import time:         0 |      32000 |     idlelib.help
import time:         0 |          0 |     idlelib.help_about
import time:         0 |          0 |     idlelib.replace
import time:         0 |          0 |     idlelib.search
import time:         0 |          0 |       idlelib.redirector
import time:         0 |          0 |     idlelib.percolator
import time:     15000 |      15000 |     idlelib.undo
import time:         0 |          0 |             _hashlib
import time:         0 |          0 |             _blake2
import time:         0 |          0 |             _sha3
import time:         0 |          0 |           hashlib
import time:         0 |          0 |             _bisect
import time:         0 |          0 |           bisect
import time:         0 |          0 |           _random
import time:         0 |          0 |         random
import time:         0 |          0 |       tempfile
import time:     16000 |      16000 |       locale
import time:         0 |      16000 |     idlelib.iomenu
import time:         0 |          0 |     idlelib.mainmenu
import time:         0 |          0 |     idlelib.statusbar
import time:         0 |          0 |     idlelib.autoexpand
import time:     15000 |      15000 |       textwrap
import time:         0 |          0 |       idlelib.calltip_w
import time:         0 |      15000 |     idlelib.calltips
import time:         0 |          0 |     idlelib.rstrip
import time:         0 |          0 |     idlelib.zoomheight
import time:         0 |     171000 |   idlelib.editor
import time:         0 |          0 |   idlelib.filelist
import time:         0 |          0 |   idlelib.outwin
import time:         0 |          0 |         _struct
import time:         0 |          0 |       struct
import time:         0 |          0 |       _compat_pickle
import time:         0 |          0 |           org
import time:         0 |          0 |         org.python
import time:         0 |          0 |       org.python.core
import time:         0 |          0 |       _pickle
import time:         0 |          0 |     pickle
import time:         0 |          0 |     queue
import time:     16000 |      16000 |     socketserver
import time:     16000 |      32000 |   idlelib.rpc
import time:         0 |          0 |     idlelib.debugobj_r
import time:         0 |          0 |         idlelib.tree
import time:         0 |          0 |       idlelib.debugobj
import time:         0 |          0 |     idlelib.stackviewer
import time:         0 |          0 |   idlelib.run
import time:         0 |          0 |   idlelib.history
import time:     30000 |     515000 | idlelib.pyshell
msg303664 - (view) Author: INADA Naoki (inada.naoki) * (Python committer) Date: 2017-10-04 01:02
https://github.com/python/cpython/blob/27c623c845dd6e4b8e1782666ca3a956636da266/Modules/timemodule.c#L80-L112

time module has perf_counter implementation based on QueryPerformanceCounter().

Could we change PyTime_GetMonotonicClock implementation to use it on Windows?

I don't want to so much code to import.c.  But if pytime.c has nice clock
for fine grained monotonic performance counter, I want to use it in
import.c.
msg303665 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-04 01:14
> Could we change PyTime_GetMonotonicClock implementation to use it on Windows?

No. See the PEP 418 for the rationale.

But we could add a _PyTime_GetPerfCounter() to Python/pytime.c.
msg304023 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-10 09:51
New changeset a997c7b434631f51e00191acea2ba6097691e859 by Victor Stinner in branch 'master':
bpo-31415: Add _PyTime_GetPerfCounter() and use it for -X importtime (#3936)
https://github.com/python/cpython/commit/a997c7b434631f51e00191acea2ba6097691e859
msg304151 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-10-11 15:39
Why global _PyTime_GetWinPerfCounterWithInfo() is needed at all? It seems to me that _PyTime_GetPerfCounterWithInfo() can be used instead. Smaller API is better.

_PyTime_GetPerfCounter() is a simple wrapper around _PyTime_GetPerfCounterWithInfo() and is used only in one place. Getting rid of it will simplify C API too.
msg304153 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-11 15:40
> Why global _PyTime_GetWinPerfCounterWithInfo() is needed at all? It seems to me that _PyTime_GetPerfCounterWithInfo() can be used instead. Smaller API is better.

I chose to expose _PyTime_GetWinPerfCounterWithInfo() to make my change as small as possible.

I didn't want to break the old time.clock() clock by mistake.

By the way, time.clock() is deprecated since Python 3.3. It's maybe time to drop it?
msg304264 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-12 15:53
Ok, the feature was implemented, the Windows clock resolution was fixed as well. It's time to close this issue.

If you still have concerns about import time, see open discussions on the python-dev mailing list, or open new issues ;-)

Thanks again Naoki INADA for this nice and useful feature!
History
Date User Action Args
2017-10-12 15:53:43hayposetstatus: open -> closed

messages: + msg304264
stage: patch review -> resolved
2017-10-11 15:40:56hayposetmessages: + msg304153
2017-10-11 15:39:21serhiy.storchakasetmessages: + msg304151
2017-10-11 14:51:27hayposetpull_requests: + pull_request3930
2017-10-10 12:35:15hayposetpull_requests: + pull_request3914
2017-10-10 09:51:55hayposetmessages: + msg304023
2017-10-09 16:44:41hayposetstage: resolved -> patch review
pull_requests: + pull_request3910
2017-10-04 01:14:45hayposetmessages: + msg303665
2017-10-04 01:02:11inada.naokisetmessages: + msg303664
2017-10-03 16:37:30terry.reedysetstatus: closed -> open
nosy: + terry.reedy
messages: + msg303628

2017-10-03 12:11:15hayposetmessages: + msg303600
2017-10-03 10:47:10inada.naokisetstatus: open -> closed
resolution: fixed
stage: patch review -> resolved
2017-10-03 10:46:36inada.naokisetmessages: + msg303593
2017-10-02 23:12:01lukasz.langasetnosy: + lukasz.langa
messages: + msg303568
2017-09-26 13:15:31hayposetnosy: + haypo
messages: + msg303039
2017-09-26 13:10:51serhiy.storchakasetmessages: + msg303038
2017-09-26 12:57:19hayposetpull_requests: + pull_request3750
2017-09-25 23:35:01inada.naokisetmessages: + msg302992
2017-09-25 10:39:50christian.heimessetnosy: + christian.heimes
messages: + msg302943
2017-09-25 02:23:02inada.naokisetmessages: + msg302906
2017-09-25 00:04:17rhettingersetmessages: + msg302895
2017-09-24 22:25:49gvanrossumsetmessages: + msg302889
2017-09-24 19:30:53rhettingersetassignee: gvanrossum

messages: + msg302882
nosy: + rhettinger, gvanrossum
2017-09-24 18:08:56inada.naokisetmessages: + msg302875
2017-09-24 10:00:08serhiy.storchakasetmessages: + msg302842
2017-09-24 09:19:38inada.naokisetmessages: + msg302839
2017-09-20 20:49:55brett.cannonsetmessages: + msg302659
2017-09-19 19:04:08serhiy.storchakasetnosy: + serhiy.storchaka
messages: + msg302559
2017-09-19 18:39:12inada.naokisetmessages: + msg302557
2017-09-19 18:35:01brett.cannonsetnosy: + brett.cannon
messages: + msg302556
2017-09-11 05:37:40inada.naokisetkeywords: + patch
stage: patch review
pull_requests: + pull_request3483
2017-09-11 05:27:15inada.naokicreate