Add -X option to show import time

[methane]

BPO	31415
Nosy	@gvanrossum, @warsaw, @brettcannon, @rhettinger, @terryjreedy, @pitrou, @vstinner, @tiran, @methane, @nschloe, @ambv, @serhiy-storchaka, @miss-islington
PRs	bpo-31415: Add -X importtime option. #3490 [WIP] bpo-31415: Add -X importtime option #3765 bpo-31415: Add _PyTime_GetPerfCounter() and use it for -X importtime #3936 bpo-31415: Rewrite _PyTime_GetWinPerfCounter() for _PyTime_t #3942 bpo-31415: Cleanup pytime.c #3955 bpo-31415: Improve caching of the importtime option. #4138 bpo-31415: Support PYTHONPROFILEIMPORTTIME envvar equivalent to -X importtime #4240 bpo-31415: importtime was made by Inada Naoki #31875 [3.9] bpo-31415: importtime was made by Inada Naoki (GH-31875) #31883 [3.10] bpo-31415: importtime was made by Inada Naoki (GH-31875) #31884
Files	sc.png

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/gvanrossum'
closed_at = <Date 2017-11-14.15:40:09.408>
created_at = <Date 2017-09-11.05:27:15.049>
labels = ['interpreter-core', 'type-feature', '3.7']
title = 'Add -X option to show import time'
updated_at = <Date 2022-03-14.21:30:22.373>
user = 'https://github.com/methane'

bugs.python.org fields:

activity = <Date 2022-03-14.21:30:22.373>
actor = 'miss-islington'
assignee = 'gvanrossum'
closed = True
closed_date = <Date 2017-11-14.15:40:09.408>
closer = 'barry'
components = ['Interpreter Core']
creation = <Date 2017-09-11.05:27:15.049>
creator = 'methane'
dependencies = []
files = ['47663']
hgrepos = []
issue_num = 31415
keywords = ['patch']
message_count = 54.0
messages = ['301858', '302556', '302557', '302559', '302659', '302839', '302842', '302875', '302882', '302889', '302895', '302906', '302943', '302992', '303038', '303039', '303568', '303593', '303600', '303628', '303664', '303665', '304023', '304151', '304153', '304264', '305071', '305093', '305108', '305109', '305449', '305458', '305462', '305490', '305493', '305505', '305515', '305516', '305517', '305522', '305523', '305533', '305558', '305559', '305562', '305565', '305603', '305712', '306219', '306326', '320841', '415170', '415194', '415196']
nosy_count = 13.0
nosy_names = ['gvanrossum', 'barry', 'brett.cannon', 'rhettinger', 'terry.reedy', 'pitrou', 'vstinner', 'christian.heimes', 'methane', 'nschloe', 'lukasz.langa', 'serhiy.storchaka', 'miss-islington']
pr_nums = ['3490', '3765', '3936', '3942', '3955', '4138', '4240', '31875', '31883', '31884']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'enhancement'
url = 'https://bugs.python.org/issue31415'
versions = ['Python 3.7']

[methane]

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]

[brettcannon]

What does the "[us]" mean?

[methane]

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>

[serhiy-storchaka]

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.

[brettcannon]

Ah, OK. Then I wouldn't put it in square brackets as it seems to suggest it's somehow disconnected from the number.

[methane]

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.

[serhiy-storchaka]

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.

[methane]

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

[rhettinger]

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).

[gvanrossum]

@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.

[rhettinger]

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).