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

Add -X option to show import time #75596

Closed
methane opened this issue Sep 11, 2017 · 54 comments
Closed

Add -X option to show import time #75596

methane opened this issue Sep 11, 2017 · 54 comments
Assignees
Labels
3.7 interpreter-core type-feature

Comments

@methane
Copy link
Member

@methane methane commented Sep 11, 2017

BPO 31415
Nosy @gvanrossum, @warsaw, @brettcannon, @rhettinger, @terryjreedy, @pitrou, @vstinner, @tiran, @methane, @nschloe, @ambv, @serhiy-storchaka, @miss-islington
PRs
  • #3490
  • #3765
  • #3936
  • #3942
  • #3955
  • #4138
  • #4240
  • #31875
  • #31883
  • #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
    Copy link
    Member Author

    @methane methane commented Sep 11, 2017

    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]

    @methane methane added 3.7 interpreter-core type-feature labels Sep 11, 2017
    @brettcannon
    Copy link
    Member

    @brettcannon brettcannon commented Sep 19, 2017

    What does the "[us]" mean?

    @methane
    Copy link
    Member Author

    @methane methane commented Sep 19, 2017

    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
    Copy link
    Member

    @serhiy-storchaka serhiy-storchaka commented Sep 19, 2017

    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
    Copy link
    Member

    @brettcannon brettcannon commented Sep 20, 2017

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

    @methane
    Copy link
    Member Author

    @methane methane commented Sep 24, 2017

    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
    Copy link
    Member

    @serhiy-storchaka serhiy-storchaka commented Sep 24, 2017

    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
    Copy link
    Member Author

    @methane methane commented Sep 24, 2017

    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
    Copy link
    Contributor

    @rhettinger rhettinger commented Sep 24, 2017

    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
    Copy link
    Member

    @gvanrossum gvanrossum commented Sep 24, 2017

    @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
    Copy link
    Contributor

    @rhettinger rhettinger commented Sep 25, 2017

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

    @methane
    Copy link
    Member Author

    @methane methane commented Sep 25, 2017

    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

    @tiran
    Copy link
    Member

    @tiran tiran commented Sep 25, 2017

    +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 bpo-31574 / PR3749 to add dtrace probes.

    @methane
    Copy link
    Member Author

    @methane methane commented Sep 25, 2017

    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 bpo-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>

    @serhiy-storchaka
    Copy link
    Member

    @serhiy-storchaka serhiy-storchaka commented Sep 26, 2017

    The output in PR 3765 partially duplicates the output of the -v option.

    @vstinner
    Copy link
    Member

    @vstinner vstinner commented Sep 26, 2017

    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.

    @ambv
    Copy link
    Contributor

    @ambv ambv commented Oct 2, 2017

    @methane
    Copy link
    Member Author

    @methane methane commented Oct 3, 2017

    New changeset 1a87de7 by INADA Naoki in branch 'master':
    bpo-31415: Add -X importtime option (GH-3490)
    1a87de7

    @methane methane closed this as completed Oct 3, 2017
    @vstinner
    Copy link
    Member

    @vstinner vstinner commented Oct 3, 2017

    Thank you Naoki for this nice enhancement! Tooling always help to take smart decisions on optimizations.

    @terryjreedy
    Copy link
    Member

    @terryjreedy terryjreedy commented Oct 3, 2017

    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

    @terryjreedy terryjreedy reopened this Oct 3, 2017
    @methane
    Copy link
    Member Author

    @methane methane commented Oct 4, 2017

    #ifdef MS_WINDOWS
    #define WIN32_PERF_COUNTER
    /* Win32 has better clock replacement; we have our own version, due to Mark
    Hammond and Tim Peters */
    static PyObject*
    win_perf_counter(_Py_clock_info_t *info)
    {
    static LONGLONG cpu_frequency = 0;
    static LONGLONG ctrStart;
    LARGE_INTEGER now;
    double diff;
    if (cpu_frequency == 0) {
    LARGE_INTEGER freq;
    QueryPerformanceCounter(&now);
    ctrStart = now.QuadPart;
    if (!QueryPerformanceFrequency(&freq) || freq.QuadPart == 0) {
    PyErr_SetFromWindowsErr(0);
    return NULL;
    }
    cpu_frequency = freq.QuadPart;
    }
    QueryPerformanceCounter(&now);
    diff = (double)(now.QuadPart - ctrStart);
    if (info) {
    info->implementation = "QueryPerformanceCounter()";
    info->resolution = 1.0 / (double)cpu_frequency;
    info->monotonic = 1;
    info->adjustable = 0;
    }
    return PyFloat_FromDouble(diff / (double)cpu_frequency);
    }
    #endif /* MS_WINDOWS */

    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.

    @vstinner
    Copy link
    Member

    @vstinner vstinner commented Oct 4, 2017

    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.

    @vstinner
    Copy link
    Member

    @vstinner vstinner commented Oct 10, 2017

    New changeset a997c7b by Victor Stinner in branch 'master':
    bpo-31415: Add _PyTime_GetPerfCounter() and use it for -X importtime (bpo-3936)
    a997c7b

    @serhiy-storchaka
    Copy link
    Member

    @serhiy-storchaka serhiy-storchaka commented Oct 11, 2017

    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.

    @methane
    Copy link
    Member Author

    @methane methane commented Oct 27, 2017

    Does it worth enough?
    I didn't think it's worth enough because import will be much slower than one dict lookup.

    @vstinner
    Copy link
    Member

    @vstinner vstinner commented Oct 27, 2017

    I didn't think it's worth enough because import will be much slower than one dict lookup.

    I don't care much of performance. For the consistency with other environment variables, I like to only read the environment variable once ("at startup"), and not do it each time.

    @methane
    Copy link
    Member Author

    @methane methane commented Oct 27, 2017

    Xoptions is not environment variable.

    Some modules are imported before xoptions are parsed.
    So negative cache for xoptions is little more complex than
    negative cache for environment variable.

    @warsaw
    Copy link
    Member

    @warsaw warsaw commented Nov 2, 2017

    I like this a lot and while the issue is still open, I'm piggybacking my PR 4240 on this one.

    I have a use case for enabling this feature via environment variable, so PR 4240 adds PYTHONPROFILEIMPORTTIME which also enables this feature.

    We build our tools using pex, which hardcodes the shebang at the top of the zip file. This isn't easily changed, and clearly we wouldn't want to enable -X importtime everywhere. When we have startup performance issues, I want to be able to tell people (or set it up in our CI) to set the environment variable and collect the data for analysis. This is much easier than tweaking the shebang or invoking the zip with an explicit command. Also, there are potential gotchas with loading too much up on the shebang line (IIRC, there are line length limits and/or multiple option limits for shebangs, e.g. if we wanted to have both -I and -X).

    I haven't fixed the initialization check problem that serhiy.storchaka points out, since that's addressed by PR 4138. But maybe I should fold that change into mine.

    @warsaw
    Copy link
    Member

    @warsaw warsaw commented Nov 2, 2017

    New changeset 700d2e4 by Barry Warsaw in branch 'master':
    bpo-31415: Support PYTHONPROFILEIMPORTTIME envvar equivalent to -X importtime (bpo-4240)
    700d2e4

    @methane
    Copy link
    Member Author

    @methane methane commented Nov 3, 2017

    When adding environment variable option, it should be documented in
    man page and python -h.

    @warsaw
    Copy link
    Member

    @warsaw warsaw commented Nov 3, 2017

    On Nov 2, 2017, at 22:50, INADA Naoki report@bugs.python.org wrote:

    When adding environment variable option, it should be documented in
    man page and python -h.

    I thought about that, but the problem is that none of the -X options are documented in the —help output. So do we only document the ones (e.g. importtime) that have an environment variable version, or do we now have to document them all?

    I opted to document PYTHONPROFILEIMPORTTIME only in the cmdline documentation.

    @serhiy-storchaka
    Copy link
    Member

    @serhiy-storchaka serhiy-storchaka commented Nov 3, 2017

    I didn't think it's worth enough because import will be much slower than one dict lookup.

    I agree. The main value of my patch is handling possible (but very unlike) errors. Implementing negative value caching adds not many lines to the existing code and additional error handling.

    But now, after adding the environment variable, do we still need the -X option? From a user side I don't see much difference between specifying an option and an environment variable, but the code for handling the environment variable is much simpler.

    @warsaw
    Copy link
    Member

    @warsaw warsaw commented Nov 3, 2017

    On Nov 3, 2017, at 11:05, Serhiy Storchaka <report@bugs.python.org> wrote:

    But now, after adding the environment variable, do we still need the -X option? From a user side I don't see much difference between specifying an option and an environment variable, but the code for handling the environment variable is much simpler.

    It’s a good question. I guess in the limited amount of time I’ve used the feature so far, I find it kind of nice to be able to type python -X importtime when doing general import profiling. The use case for the environment variable is more compelling IMHO which is why I really wanted to add it. I suppose typing PYTHONPROFILEIMPORTTIME=x python isn’t too onerous, even if it is kind of a weird long mashed together word.

    I suppose I’m -0 on removing the -X option, and +0 on adding the negative cache.

    @terryjreedy
    Copy link
    Member

    @terryjreedy terryjreedy commented Nov 3, 2017

    PYTHONPROFILEIMPORTTIME=x python isn’t too onerous

    It does not work on Windows.

    C:\Users\Terry>PYTHONPROFILEIMPORTTIME=x python
    'PYTHONPROFILEIMPORTTIME' is not recognized as an internal or external command, operable program or batch file.

    Does it set the EV for the entire session (which one likely would not want), or just the one command (which has no Windows equivalent that I know of)? Please leave the easily remembered and typed option.

    @serhiy-storchaka
    Copy link
    Member

    @serhiy-storchaka serhiy-storchaka commented Nov 3, 2017

    Note that with environment variable you get more information.

    $ ./python -X importtime -c pass
    import time: self [us] | cumulative | imported package
    import time:        88 |         88 |     _codecs
    import time:       789 |        876 |   codecs
    import time:       602 |        602 |   encodings.aliases
    import time:       809 |       2287 | encodings
    ...
    
    $ PYTHONPROFILEIMPORTTIME=1 ./python -c pass
    import time: self [us] | cumulative | imported package
    import time:      3133 |       3133 | _frozen_importlib_external
    import time:       371 |        371 | zipimport
    import time:       327 |        327 |     _codecs
    import time:      2656 |       2982 |   codecs
    import time:      1821 |       1821 |   encodings.aliases
    import time:      2604 |       7406 | encodings
    ...

    @serhiy-storchaka
    Copy link
    Member

    @serhiy-storchaka serhiy-storchaka commented Nov 3, 2017

    On Windows you can create a 2-line bat-file that sets the environment variable and runs Python.

    @warsaw
    Copy link
    Member

    @warsaw warsaw commented Nov 3, 2017

    On Nov 3, 2017, at 14:41, Serhiy Storchaka <report@bugs.python.org> wrote:

    Note that with environment variable you get more information.

    Fun!

    @warsaw
    Copy link
    Member

    @warsaw warsaw commented Nov 3, 2017

    On Nov 3, 2017, at 14:23, Terry J. Reedy <report@bugs.python.org> wrote:

    Does it set the EV for the entire session (which one likely would not want), or just the one command (which has no Windows equivalent that I know of)? Please leave the easily remembered and typed option.

    On *nix, this sets the environment variable for just this process.

    @methane
    Copy link
    Member Author

    @methane methane commented Nov 4, 2017

    I'm +1 to remove -X option.
    Supporting both form makes code ugly and benefit is too small.
    And +1 to negative cache too. It's simple for environment varianle.

    @pitrou
    Copy link
    Member

    @pitrou pitrou commented Nov 4, 2017

    One benefit (or drawback, depending on how you see it) of the -X option is that it wouldn't propagate to child processes spawned by multiprocessing. See _args_from_interpreter_flags() in Lib/subprocess.py.

    More generally, the idea that we should remove a command line option because there's an environment variable sounds dubious to me. Should we do the same for all command-line options? The faulthandler module can be enabled either using the PYTHONFAULTHANDLER environment variable or by specifying -X faulthandler on the command line.

    The only serious reason I can imagine would be that the -X option has a significant maintenance cost.

    @pitrou
    Copy link
    Member

    @pitrou pitrou commented Nov 4, 2017

    (and Terry is right that environment variables can be significantly more annoying on Windows)

    @warsaw
    Copy link
    Member

    @warsaw warsaw commented Nov 4, 2017

    Okay, given the non-propagation and Windows issues. I'm -1 on removing -X, +1 on fixing the negative cache.

    @terryjreedy
    Copy link
    Member

    @terryjreedy terryjreedy commented Nov 4, 2017

    with environment variable you get more information.

    For timing package import time, such as for idlelib.pyshell, rather than bare python startup time, the extra information is just a bit more noise to ignore.

    The importtime output is sent to stderr. Should this be documented? It is important because displaying results immediately on command prompt rather than redirecting to a file adds about .07 seconds to the total time reported for pyshell, whether I use debug or normal binaries. The relative variation between repeated runs (about 1%) also seems less with redirection to a file.

    @warsaw
    Copy link
    Member

    @warsaw warsaw commented Nov 5, 2017

    On Nov 4, 2017, at 14:29, Terry J. Reedy <report@bugs.python.org> wrote:

    The importtime output is sent to stderr. Should this be documented?

    Yes. :)

    @serhiy-storchaka
    Copy link
    Member

    @serhiy-storchaka serhiy-storchaka commented Nov 7, 2017

    New changeset 088929c by Serhiy Storchaka in branch 'master':
    bpo-31415: Improve error handling and caching of the importtime option. (bpo-4138)
    088929c

    @warsaw
    Copy link
    Member

    @warsaw warsaw commented Nov 14, 2017

    I think there is nothing left to do for this issue, so I'm closing it.

    @warsaw warsaw closed this as completed Nov 14, 2017
    @vstinner
    Copy link
    Member

    @vstinner vstinner commented Nov 16, 2017

    FYI I'm working on the Py_Main() function in bpo-32030. My latest PR (PR 4412) moves the code to parse -X importtime and PYTHONPROFILEIMPORTTIME into Py_Main(), to group all functions parsing the command line arguments and environment variables.

    With this change, the "importtime" option is now checked before the very first "Python" function call.

    The new code doesn't use the sys module anymore to parse -X options, and so break the dependency between "importtime", the import machinery and the sys module.

    @nschloe
    Copy link
    Mannequin

    @nschloe nschloe mannequin commented Jul 1, 2018

    I just updated tuna [1] to support import time profiles as well.
    Install with

    pip install tuna
    

    and use with

    python -X importprofile yourfile.py 2> import.log
    tuna import.log
    

    See screenshot for example output.

    Cheers,
    Nico

    [1] https://github.com/nschloe/tuna

    @gvanrossum
    Copy link
    Member

    @gvanrossum gvanrossum commented Mar 14, 2022

    New changeset 29624e7 by Victor Stinner in branch 'main':
    bpo-31415: importtime was made by Inada Naoki (GH-31875)
    29624e7

    @miss-islington
    Copy link
    Contributor

    @miss-islington miss-islington commented Mar 14, 2022

    New changeset 9f1587e by Miss Islington (bot) in branch '3.10':
    bpo-31415: importtime was made by Inada Naoki (GH-31875)
    9f1587e

    @miss-islington
    Copy link
    Contributor

    @miss-islington miss-islington commented Mar 14, 2022

    New changeset 73943ce by Miss Islington (bot) in branch '3.9':
    bpo-31415: importtime was made by Inada Naoki (GH-31875)
    73943ce

    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    3.7 interpreter-core type-feature
    Projects
    None yet
    Development

    No branches or pull requests