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

Jump to bottom

Add dtrace hook for importlib #75755

Closed
tiran opened this issue Sep 25, 2017 · 6 comments
Closed

Add dtrace hook for importlib #75755

tiran opened this issue Sep 25, 2017 · 6 comments
Labels
3.7 (EOL) end of life interpreter-core (Objects, Python, Grammar, and Parser dirs) performance Performance or resource usage

Comments

@tiran
Copy link
Member

tiran commented Sep 25, 2017

BPO 31574
Nosy @warsaw, @brettcannon, @ncoghlan, @tiran, @ambv, @ericsnowcurrently
PRs
  • bpo-31574: importlib dtrace #3749
    		•
    Files
  • import.stp
  • import.stp
    		•

    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 = None
closed_at = <Date 2017-09-29.22:54:13.218>
created_at = <Date 2017-09-25.10:32:40.023>
labels = ['interpreter-core', '3.7', 'performance']
title = 'Add dtrace hook for importlib'
updated_at = <Date 2017-09-29.22:54:13.217>
user = 'https://github.com/tiran'

    bugs.python.org fields:

    activity = <Date 2017-09-29.22:54:13.217>
actor = 'lukasz.langa'
assignee = 'none'
closed = True
closed_date = <Date 2017-09-29.22:54:13.218>
closer = 'lukasz.langa'
components = ['Interpreter Core']
creation = <Date 2017-09-25.10:32:40.023>
creator = 'christian.heimes'
dependencies = []
files = ['47168', '47169']
hgrepos = []
issue_num = 31574
keywords = ['patch']
message_count = 6.0
messages = ['302942', '302951', '302954', '303367', '303368', '303369']
nosy_count = 6.0
nosy_names = ['barry', 'brett.cannon', 'ncoghlan', 'christian.heimes', 'lukasz.langa', 'eric.snow']
pr_nums = ['3749']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'performance'
url = 'https://bugs.python.org/issue31574'
versions = ['Python 3.7']
    @tiran
    Copy link
    Member Author

    tiran commented Sep 25, 2017

    bpo-31415 proposed an option to show import timings. The output is primarily designed for humans. I propose to instrument importlib with two dtrace hooks:

    probe import__find__load__start(const char *)
    probe import__find__load__done(const char *, int);

    arg0 is the absolute module name as UTF-8 string. arg1 of import_find_load_done probe indicates if the module was found (1) or import failed (0).

    @tiran tiran added 3.7 (EOL) end of life interpreter-core (Objects, Python, Grammar, and Parser dirs) performance Performance or resource usage labels Sep 25, 2017
    @tiran
    Copy link
    Member Author

    tiran commented Sep 25, 2017

    Example output:

    $ sudo stap import.stp -c "./python -c pass"
[1506342342142233574] * Importing '_frozen_importlib_external' ...
[1506342342142719538] + Imported  '_frozen_importlib_external'
[1506342342143260191] * Importing 'zipimport' ...
[1506342342143329476] + Imported  'zipimport'
[1506342342143474571] * Importing 'encodings' ...
[1506342342143858228]   * Importing 'codecs' ...
[1506342342144149624]     * Importing '_codecs' ...
[1506342342144205933]     + Imported  '_codecs'
[1506342342144363609]   + Imported  'codecs'
[1506342342144377843]   * Importing 'encodings.aliases' ...
[1506342342144676180]   + Imported  'encodings.aliases'
[1506342342144712610] + Imported  'encodings'
[1506342342144725110] * Importing 'encodings.utf_8' ...
[1506342342144906782] + Imported  'encodings.utf_8'
[1506342342144925714] * Importing '_signal' ...
[1506342342145015138] + Imported  '_signal'
[1506342342145025346] * Importing 'encodings.latin_1' ...
[1506342342145229859] + Imported  'encodings.latin_1'
[1506342342145236273] * Importing 'io' ...
[1506342342145333476]   * Importing 'abc' ...
[1506342342145443604]     * Importing '_weakrefset' ...
[1506342342145658942]     + Imported  '_weakrefset'
[1506342342145746442]   + Imported  'abc'
[1506342342145929972] + Imported  'io'
[1506342342145985754] * Importing 'site' ...
[1506342342146168933]   * Importing 'os' ...
[1506342342146387697]     * Importing 'errno' ...
[1506342342146455581]     + Imported  'errno'
[1506342342146457808]     * Importing 'stat' ...
[1506342342146620691]       * Importing '_stat' ...
[1506342342146676954]       + Imported  '_stat'
[1506342342146700059]     + Imported  'stat'
[1506342342146738715]     * Importing 'posixpath' ...
[1506342342146882603]       * Importing 'genericpath' ...
[1506342342146999370]       + Imported  'genericpath'
[1506342342147014839]     + Imported  'posixpath'
[1506342342147133401]     * Importing '_collections_abc' ...
[1506342342148404142]     + Imported  '_collections_abc'
[1506342342148517849]   + Imported  'os'
[1506342342148521360]   * Importing '_sitebuiltins' ...
[1506342342148680131]   + Imported  '_sitebuiltins'
[1506342342148952120]   * Importing 'sitecustomize' ...
[1506342342149107151]   - Failed    'sitecustomize'
[1506342342149111461]   * Importing 'usercustomize' ...
[1506342342149171745]   - Failed    'usercustomize'
[1506342342149182576] + Imported  'site'

    @tiran
    Copy link
    Member Author

    tiran commented Sep 25, 2017

    Improved script and output for "import asyncio":

    $ sudo stap import.stp -c "./python -c 'import asyncio'"
[1506343527655342994] * Importing '_frozen_importlib_external' ...
[1506343527655797118] + Imported  '_frozen_importlib_external' in 454us
[1506343527656351387] * Importing 'zipimport' ...
[1506343527656420328] + Imported  'zipimport' in 68us
[1506343527656577490] * Importing 'encodings' ...
[1506343527656969001]   * Importing 'codecs' ...
[1506343527657242647]     * Importing '_codecs' ...
[1506343527657302163]     + Imported  '_codecs' in 59us
[1506343527657461354]   + Imported  'codecs' in 492us
[1506343527657475610]   * Importing 'encodings.aliases' ...
[1506343527657778342]   + Imported  'encodings.aliases' in 302us
[1506343527657815834] + Imported  'encodings' in 1238us
[1506343527657829245] * Importing 'encodings.utf_8' ...
[1506343527658013466] + Imported  'encodings.utf_8' in 184us
[1506343527658037373] * Importing '_signal' ...
[1506343527658133293] + Imported  '_signal' in 95us
[1506343527658144146] * Importing 'encodings.latin_1' ...
[1506343527658350574] + Imported  'encodings.latin_1' in 206us
[1506343527658357616] * Importing 'io' ...
[1506343527658456592]   * Importing 'abc' ...
[1506343527658570293]     * Importing '_weakrefset' ...
[1506343527658790316]     + Imported  '_weakrefset' in 219us
[1506343527658881770]   + Imported  'abc' in 425us
[1506343527659074176] + Imported  'io' in 716us
[1506343527659130999] * Importing 'site' ...
[1506343527659303251]   * Importing 'os' ...
[1506343527659525410]     * Importing 'errno' ...
[1506343527659597020]     + Imported  'errno' in 71us
[1506343527659599466]     * Importing 'stat' ...
[1506343527659766912]       * Importing '_stat' ...
[1506343527659826033]       + Imported  '_stat' in 59us
[1506343527659850009]     + Imported  'stat' in 250us
[1506343527659890059]     * Importing 'posixpath' ...
[1506343527660042891]       * Importing 'genericpath' ...
[1506343527660162920]       + Imported  'genericpath' in 119us
[1506343527660178776]     + Imported  'posixpath' in 288us
[1506343527660291984]     * Importing '_collections_abc' ...
[1506343527661557288]     + Imported  '_collections_abc' in 1265us
[1506343527661673583]   + Imported  'os' in 2370us
[1506343527661677360]   * Importing '_sitebuiltins' ...
[1506343527661838265]   + Imported  '_sitebuiltins' in 160us
[1506343527662126078]   * Importing 'sitecustomize' ...
[1506343527662277259]   - Failed    'sitecustomize' in 151us
[1506343527662281831]   * Importing 'usercustomize' ...
[1506343527662342158]   - Failed    'usercustomize' in 60us
[1506343527662352810] + Imported  'site' in 3221us
[1506343527662533328] * Importing 'asyncio' ...
[1506343527662726586]   * Importing 'asyncio.selectors' ...
[1506343527662819261]   - Failed    'asyncio.selectors' in 92us
[1506343527662828182]   * Importing 'selectors' ...
[1506343527662998225]     * Importing 'collections' ...
[1506343527663394147]       * Importing 'operator' ...
[1506343527663966898]         * Importing '_operator' ...
[1506343527664053199]         + Imported  '_operator' in 86us
[1506343527664080513]       + Imported  'operator' in 686us
[1506343527664084065]       * Importing 'keyword' ...
[1506343527664212162]       + Imported  'keyword' in 128us
[1506343527664217270]       * Importing 'heapq' ...
[1506343527664344952]         * Importing '_heapq' ...
[1506343527664482616]         + Imported  '_heapq' in 137us
[1506343527664500526]       + Imported  'heapq' in 283us
[1506343527664504388]       * Importing 'itertools' ...
[1506343527664598920]       + Imported  'itertools' in 94us
[1506343527664603801]       * Importing 'reprlib' ...
[1506343527664775143]       + Imported  'reprlib' in 171us
[1506343527664779385]       * Importing '_collections' ...
[1506343527664845585]       + Imported  '_collections' in 66us
[1506343527665283918]     + Imported  'collections' in 2285us
[1506343527665287954]     * Importing 'collections.abc' ...
[1506343527665431913]     + Imported  'collections.abc' in 143us
[1506343527665435709]     * Importing 'math' ...
[1506343527665598221]     + Imported  'math' in 162us
[1506343527665600676]     * Importing 'select' ...
[1506343527665748069]     + Imported  'select' in 147us
[1506343527666097689]   + Imported  'selectors' in 3269us
[1506343527666102503]   * Importing 'asyncio.base_events' ...
[1506343527666436554]     * Importing 'concurrent.futures' ...
[1506343527666449899]       * Importing 'concurrent' ...
[1506343527666575660]       + Imported  'concurrent' in 125us
[1506343527666696868]       * Importing 'concurrent.futures._base' ...
[1506343527666880942]         * Importing 'logging' ...
[1506343527667272107]           * Importing 'time' ...
[1506343527667364105]           + Imported  'time' in 91us
[1506343527667366876]           * Importing 'traceback' ...
[1506343527667538062]             * Importing 'linecache' ...
[1506343527667655837]               * Importing 'functools' ...
[1506343527667853232]                 * Importing '_functools' ...
[1506343527667950423]                 + Imported  '_functools' in 97us
[1506343527667956988]                 * Importing 'types' ...
[1506343527668187489]                 + Imported  'types' in 230us
[1506343527668191976]                 * Importing 'weakref' ...
[1506343527668554118]                 + Imported  'weakref' in 362us
[1506343527668772860]               + Imported  'functools' in 1116us
[1506343527668776745]               * Importing 'tokenize' ...
[1506343527668977555]                 * Importing 're' ...
[1506343527669125952]                   * Importing 'enum' ...
[1506343527669665034]                   + Imported  'enum' in 539us
[1506343527669667630]                   * Importing 'sre_compile' ...
[1506343527669841045]                     * Importing '_sre' ...
[1506343527669972940]                     + Imported  '_sre' in 131us
[1506343527669975152]                     * Importing 'sre_parse' ...
[1506343527670170711]                       * Importing 'sre_constants' ...
[1506343527670422068]                       + Imported  'sre_constants' in 251us
[1506343527670520794]                     + Imported  'sre_parse' in 545us
[1506343527670572631]                   + Imported  'sre_compile' in 904us
[1506343527670575418]                   * Importing '_locale' ...
[1506343527670651295]                   + Imported  '_locale' in 75us
[1506343527670915323]                   * Importing 'copyreg' ...
[1506343527671068681]                   + Imported  'copyreg' in 153us
[1506343527671094674]                 + Imported  're' in 2117us
[1506343527671098023]                 * Importing 'token' ...
[1506343527671254170]                 + Imported  'token' in 156us
[1506343527672052976]               + Imported  'tokenize' in 3276us
[1506343527672062179]             + Imported  'linecache' in 4524us
[1506343527672123907]           + Imported  'traceback' in 4757us
[1506343527672125845]           * Importing 'warnings' ...
[1506343527672371662]           + Imported  'warnings' in 245us
[1506343527672375147]           * Importing 'string' ...
[1506343527672519582]             * Importing '_string' ...
[1506343527672561187]             + Imported  '_string' in 41us
[1506343527673839738]           + Imported  'string' in 1464us
[1506343527673845483]           * Importing 'threading' ...
[1506343527674338798]           + Imported  'threading' in 493us
[1506343527674590202]           * Importing 'atexit' ...
[1506343527674633752]           + Imported  'atexit' in 43us
[1506343527674665516]         + Imported  'logging' in 7784us
[1506343527674888380]       + Imported  'concurrent.futures._base' in 8191us
[1506343527674894686]       * Importing 'concurrent.futures.process' ...
[1506343527675091336]         * Importing 'queue' ...
[1506343527675371422]         + Imported  'queue' in 280us
[1506343527675375826]         * Importing 'multiprocessing' ...
[1506343527675512281]           * Importing 'multiprocessing.context' ...
[1506343527675720638]             * Importing 'multiprocessing.process' ...
[1506343527675859290]               * Importing 'signal' ...
[1506343527676758864]               + Imported  'signal' in 899us
[1506343527676870972]             + Imported  'multiprocessing.process' in 1150us
[1506343527676886947]             * Importing 'multiprocessing.reduction' ...
[1506343527677041218]               * Importing 'pickle' ...
[1506343527677385368]                 * Importing 'struct' ...
[1506343527677495592]                   * Importing '_struct' ...
[1506343527677666157]                   + Imported  '_struct' in 170us
[1506343527677680292]                 + Imported  'struct' in 294us
[1506343527677684987]                 * Importing '_compat_pickle' ...
[1506343527677961681]                 + Imported  '_compat_pickle' in 276us
[1506343527678041643]                 * Importing 'org.python.core' ...
[1506343527678054775]                   * Importing 'org.python' ...
[1506343527678063151]                     * Importing 'org' ...
[1506343527678160022]                     - Failed    'org' in 96us
[1506343527678165477]                   - Failed    'org.python' in 110us
[1506343527678169806]                 - Failed    'org.python.core' in 128us
[1506343527678453584]                 * Importing '_pickle' ...
[1506343527678682557]                 + Imported  '_pickle' in 228us
[1506343527678699477]               + Imported  'pickle' in 1658us
[1506343527678701372]               * Importing 'socket' ...
[1506343527679014499]                 * Importing '_socket' ...
[1506343527679305431]                 + Imported  '_socket' in 290us
[1506343527681182408]               + Imported  'socket' in 2480us
[1506343527681225095]               * Importing 'array' ...
[1506343527681396825]               + Imported  'array' in 171us
[1506343527681464750]             + Imported  'multiprocessing.reduction' in 4577us
[1506343527681680992]           + Imported  'multiprocessing.context' in 6168us
[1506343527681711076]         + Imported  'multiprocessing' in 6335us
[1506343527681714776]         * Importing 'multiprocessing.connection' ...
[1506343527681953389]           * Importing 'tempfile' ...
[1506343527682231391]             * Importing 'shutil' ...
[1506343527682459094]               * Importing 'fnmatch' ...
[1506343527682590893]               + Imported  'fnmatch' in 131us
[1506343527682593628]               * Importing 'zlib' ...
[1506343527682812201]               + Imported  'zlib' in 218us
[1506343527682815000]               * Importing 'bz2' ...
[1506343527682960875]                 * Importing '_compression' ...
[1506343527683168744]                 + Imported  '_compression' in 207us
[1506343527683173386]                 * Importing '_bz2' ...
[1506343527683355598]                 + Imported  '_bz2' in 182us
[1506343527683415441]               + Imported  'bz2' in 600us
[1506343527683417690]               * Importing 'lzma' ...
[1506343527683618430]                 * Importing '_lzma' ...
[1506343527683847351]                 + Imported  '_lzma' in 228us
[1506343527683914653]               + Imported  'lzma' in 496us
[1506343527683916892]               * Importing 'pwd' ...
[1506343527683964576]               + Imported  'pwd' in 47us
[1506343527683967819]               * Importing 'grp' ...
[1506343527684104261]               + Imported  'grp' in 136us
[1506343527684307372]             + Imported  'shutil' in 2075us
[1506343527684310290]             * Importing 'random' ...
[1506343527684513408]               * Importing 'hashlib' ...
[1506343527684647234]                 * Importing '_hashlib' ...
[1506343527685952916]                 + Imported  '_hashlib' in 1305us
[1506343527685981208]                 * Importing '_blake2' ...
[1506343527686135520]                 + Imported  '_blake2' in 154us
[1506343527686144167]                 * Importing '_sha3' ...
[1506343527686301852]                 + Imported  '_sha3' in 157us
[1506343527686325095]               + Imported  'hashlib' in 1811us
[1506343527686329270]               * Importing 'bisect' ...
[1506343527686469216]                 * Importing '_bisect' ...
[1506343527686599171]                 + Imported  '_bisect' in 129us
[1506343527686618597]               + Imported  'bisect' in 289us
[1506343527686644405]               * Importing '_random' ...
[1506343527686770076]               + Imported  '_random' in 125us
[1506343527686923662]             + Imported  'random' in 2613us
[1506343527687013051]           + Imported  'tempfile' in 5059us
[1506343527687015501]           * Importing '_multiprocessing' ...
[1506343527687165857]           + Imported  '_multiprocessing' in 150us
[1506343527687174212]           * Importing 'multiprocessing.util' ...
[1506343527687333150]             * Importing 'subprocess' ...
[1506343527687627854]               * Importing '_posixsubprocess' ...
[1506343527687763956]               + Imported  '_posixsubprocess' in 136us
[1506343527687825343]             + Imported  'subprocess' in 492us
[1506343527687894134]           + Imported  'multiprocessing.util' in 719us
[1506343527687903826]           * Importing '_winapi' ...
[1506343527688000281]           - Failed    '_winapi' in 96us
[1506343527688114571]         + Imported  'multiprocessing.connection' in 6399us
[1506343527688218537]       + Imported  'concurrent.futures.process' in 13323us
[1506343527688223321]       * Importing 'concurrent.futures.thread' ...
[1506343527688456689]       + Imported  'concurrent.futures.thread' in 233us
[1506343527688469596]     + Imported  'concurrent.futures' in 22033us
[1506343527688486542]     * Importing 'asyncio.coroutines' ...
[1506343527688627214]       * Importing 'inspect' ...
[1506343527689051520]         * Importing 'ast' ...
[1506343527689201465]           * Importing '_ast' ...
[1506343527690360366]           + Imported  '_ast' in 1158us
[1506343527690418976]         + Imported  'ast' in 1367us
[1506343527690421460]         * Importing 'dis' ...
[1506343527690609358]           * Importing 'opcode' ...
[1506343527690744126]             * Importing '_opcode' ...
[1506343527690868136]             + Imported  '_opcode' in 123us
[1506343527690960986]           + Imported  'opcode' in 351us
[1506343527691146503]         + Imported  'dis' in 724us
[1506343527691150563]         * Importing 'importlib.machinery' ...
[1506343527691160868]           * Importing 'importlib' ...
[1506343527691322776]           + Imported  'importlib' in 161us
[1506343527691477264]         + Imported  'importlib.machinery' in 326us
[1506343527692443766]       + Imported  'inspect' in 3816us
[1506343527692460220]       * Importing 'asyncio.compat' ...
[1506343527692569504]       + Imported  'asyncio.compat' in 109us
[1506343527692583296]       * Importing 'asyncio.events' ...
[1506343527692922640]       + Imported  'asyncio.events' in 339us
[1506343527692938658]       * Importing 'asyncio.base_futures' ...
[1506343527693089146]       + Imported  'asyncio.base_futures' in 150us
[1506343527693097019]       * Importing 'asyncio.log' ...
[1506343527693202749]       + Imported  'asyncio.log' in 105us
[1506343527693271416]     + Imported  'asyncio.coroutines' in 4784us
[1506343527693288981]     * Importing 'asyncio.futures' ...
[1506343527693458684]       * Importing '_asyncio' ...
[1506343527693590612]         * Importing 'asyncio.base_tasks' ...
[1506343527693773092]         + Imported  'asyncio.base_tasks' in 182us
[1506343527693842228]       + Imported  '_asyncio' in 383us
[1506343527693852041]     + Imported  'asyncio.futures' in 563us
[1506343527693864188]     * Importing 'asyncio.tasks' ...
[1506343527694138460]     + Imported  'asyncio.tasks' in 274us
[1506343527694280454]   + Imported  'asyncio.base_events' in 28177us
[1506343527694297359]   * Importing 'asyncio.locks' ...
[1506343527694614453]   + Imported  'asyncio.locks' in 317us
[1506343527694620448]   * Importing 'asyncio.protocols' ...
[1506343527694792552]   + Imported  'asyncio.protocols' in 172us
[1506343527694798376]   * Importing 'asyncio.queues' ...
[1506343527695097901]   + Imported  'asyncio.queues' in 299us
[1506343527695103983]   * Importing 'asyncio.streams' ...
[1506343527695473686]   + Imported  'asyncio.streams' in 369us
[1506343527695480408]   * Importing 'asyncio.subprocess' ...
[1506343527695719112]   + Imported  'asyncio.subprocess' in 238us
[1506343527695729172]   * Importing 'asyncio.transports' ...
[1506343527696016855]   + Imported  'asyncio.transports' in 287us
[1506343527696029914]   * Importing 'asyncio.unix_events' ...
[1506343527696299055]     * Importing 'asyncio.base_subprocess' ...
[1506343527696537313]     + Imported  'asyncio.base_subprocess' in 238us
[1506343527696551179]     * Importing 'asyncio.constants' ...
[1506343527696647867]     + Imported  'asyncio.constants' in 96us
[1506343527696671004]     * Importing 'asyncio.selector_events' ...
[1506343527696935782]       * Importing 'ssl' ...
[1506343527697203621]         * Importing 'ipaddress' ...
[1506343527698733687]         + Imported  'ipaddress' in 1529us
[1506343527698736413]         * Importing 'textwrap' ...
[1506343527700241685]         + Imported  'textwrap' in 1505us
[1506343527700251270]         * Importing '_ssl' ...
[1506343527700771099]         + Imported  '_ssl' in 519us
[1506343527701895432]         * Importing 'base64' ...
[1506343527702093269]           * Importing 'binascii' ...
[1506343527702264128]           + Imported  'binascii' in 170us
[1506343527702283455]         + Imported  'base64' in 387us
[1506343527702758006]       + Imported  'ssl' in 5822us
[1506343527702792106]       * Importing 'asyncio.sslproto' ...
[1506343527703082171]       + Imported  'asyncio.sslproto' in 289us
[1506343527703230568]     + Imported  'asyncio.selector_events' in 6559us
[1506343527703427890]   + Imported  'asyncio.unix_events' in 7397us
[1506343527703441772] + Imported  'asyncio' in 40908us

    @ambv
    Copy link
    Contributor

    ambv commented Sep 29, 2017

    Amazing!

    @ambv
    Copy link
    Contributor

    ambv commented Sep 29, 2017

    New changeset 3d2b407 by Łukasz Langa (Christian Heimes) in branch 'master':
    bpo-31574: importlib dtrace (bpo-3749)
    3d2b407

    @ambv
    Copy link
    Contributor

    ambv commented Sep 29, 2017

    Merged. Thanks! ✨ 🍰 ✨

    @ambv ambv closed this as completed Sep 29, 2017
    @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
    Assignees
    No one assigned
    Labels
    3.7 (EOL) end of life interpreter-core (Objects, Python, Grammar, and Parser dirs) performance Performance or resource usage
    Projects
    None yet
    Milestone
    No milestone
    Development

    No branches or pull requests
    2 participants
    @ambv @tiran