Add dtrace hook for importlib

[tiran]

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]

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]

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]

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]

Amazing!

[ambv]

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

[ambv]

Merged. Thanks! ✨ 🍰 ✨