python -X importtime shows negative import time for certain import

[jonathandung]

Bug report

Bug description:

I found this issue when working on my library called asyncutils, and find it hard to reproduce. Basically,

python -m asyncutils

is meant to enter my custom console, in which I execute PYTHONSTARTUP. When I run this command in a VS Code terminal, PYTHONSTARTUP has already been set automatically, pointing to a .py file which imports the platform module. When I do:

python -X importtime -m asyncutils 2>.out/importtime.txt

I see this output in .out/importtime.txt:

import time: self [us] | cumulative | imported package
import time:       201 |        201 | winreg
import time:       268 |        268 |   _io
import time:        56 |         56 |   marshal
import time:       252 |        252 |   nt
import time:      1191 |       1765 | _frozen_importlib_external
import time:       508 |        508 |   time
import time:       445 |        952 | zipimport
import time:        63 |         63 |     _codecs
import time:       892 |        954 |   codecs
import time:      1334 |       1334 |   encodings.aliases
import time:       742 |        742 |   encodings._win_cp_codecs
import time:      2334 |       5363 | encodings
import time:       852 |        852 | encodings.utf_8
import time:       995 |        995 | encodings.cp1252
import time:       200 |        200 | _signal
import time:        48 |         48 |       _abc
import time:       265 |        313 |     abc
import time:        64 |         64 |       _stat
import time:       285 |        348 |     stat
import time:       843 |        843 |     _collections_abc
import time:       142 |        142 |       genericpath
import time:       152 |        152 |       _winapi
import time:       565 |        859 |     ntpath
import time:       963 |       3325 |   os
import time:       143 |        143 |   _sitebuiltins
import time:       110 |        110 |   errno
import time:       577 |        577 |   encodings.utf_8_sig
import time:       552 |        552 |     __future__
import time:       586 |        586 |       importlib
import time:       177 |        762 |     importlib.machinery
import time:        56 |         56 |         _contextvars
import time:       720 |        776 |       _py_warnings
import time:       628 |       1404 |     warnings
import time:       828 |        828 |       importlib._abc
import time:        58 |         58 |         _types
import time:       705 |        763 |       types
import time:       344 |       1934 |     importlib.util
import time:       201 |        201 |     itertools
import time:       217 |        217 |       io
import time:       125 |        125 |         _operator
import time:       917 |       1042 |       operator
import time:       205 |        205 |         posix
import time:       161 |        161 |         posix
import time:       284 |        649 |       posixpath
import time:       435 |        435 |             keyword
import time:       604 |        604 |             reprlib
import time:       124 |        124 |             _collections
import time:      1448 |       2610 |           collections
import time:        80 |         80 |             _functools
import time:      1275 |       1354 |           functools
import time:      1056 |       5018 |         contextlib
import time:      1600 |       1600 |           enum
import time:        91 |         91 |             _sre
import time:       571 |        571 |               re._constants
import time:      1022 |       1592 |             re._parser
import time:       562 |        562 |             re._casefix
import time:      1117 |       3361 |           re._compiler
import time:       527 |        527 |           copyreg
import time:      1340 |       6826 |         re
import time:       682 |        682 |         fnmatch
import time:      1228 |      13754 |       glob
import time:       212 |        212 |       pwd
import time:       151 |        151 |       grp
import time:       229 |        229 |         fcntl
import time:       260 |        260 |         posix
import time:      1283 |       1772 |       pathlib._os
import time:      2028 |      19821 |     pathlib
import time:      2323 |      26995 |   __editable___py_asyncutils_0_8_28_finder
import time:      1241 |       1241 |   _distutils_hack
import time:       173 |        173 |   sitecustomize
import time:       148 |        148 |   usercustomize
import time:      4922 |      37631 | site
import time:       264 |        264 | runpy
import time:      1213 |       1213 |       asyncutils._internal
import time:      1210 |       1210 |       asyncutils._internal.patch
import time:        77 |         77 |         atexit
import time:      1382 |       1459 |       asyncutils._internal.helpers
import time:      1210 |       1210 |       asyncutils._internal.submodules
import time:      3120 |       8210 |     asyncutils.exceptions
import time:       115 |        115 |     math
import time:      2068 |      10393 |   asyncutils.version
import time:      1400 |      11793 | asyncutils
import time:       515 |        515 | asyncutils.cli
import time:       428 |        428 |           linecache
import time:      1230 |       1230 |           textwrap
import time:       761 |        761 |           codeop
import time:       556 |        556 |             token
import time:        77 |         77 |             _tokenize
import time:      1463 |       2095 |           tokenize
import time:       516 |        516 |                   _weakrefset
import time:      1065 |       1581 |                 weakref
import time:      1072 |       2652 |               copy
import time:      1061 |       1061 |                     _ast
import time:       889 |       1949 |                   ast
import time:      1282 |       3231 |                 annotationlib
import time:        64 |         64 |                     _opcode
import time:       801 |        801 |                     _opcode_metadata
import time:      1115 |       1979 |                   opcode
import time:      1836 |       3815 |                 dis
import time:      3551 |      10596 |               inspect
import time:      1329 |      14576 |             dataclasses
import time:      8855 |      23431 |           _colorize
import time:      1622 |      29565 |         traceback
import time:        68 |         68 |           _string
import time:      1189 |       1257 |         string
import time:      1115 |       1115 |         threading
import time:      2476 |      34412 |       logging
import time:       664 |      35075 |     asyncutils._internal.log
import time:      1342 |       1342 |     asyncutils._internal.unparsed
import time:       700 |        700 |       asyncutils.constants
import time:        75 |         75 |         _heapq
import time:       579 |        579 |                 concurrent
import time:      1416 |       1416 |                 concurrent.futures._base
import time:       119 |        119 |                 _interpreters
import time:       991 |       3103 |               concurrent.futures
import time:       764 |        764 |               heapq
import time:      2140 |       2140 |                 _socket
import time:      1884 |       4024 |               socket
import time:        90 |         90 |                   _locale
import time:      1607 |       1696 |                 locale
import time:       932 |        932 |                 signal
import time:       251 |        251 |                 fcntl
import time:        87 |         87 |                 msvcrt
import time:      1556 |       4519 |               subprocess
import time:      4172 |       4172 |                 _ssl
import time:       112 |        112 |                     _struct
import time:       822 |        934 |                   struct
import time:       132 |        132 |                   binascii
import time:      1353 |       2418 |                 base64
import time:      4660 |      11249 |               ssl
import time:       851 |        851 |               asyncio.constants
import time:       724 |        724 |               asyncio.coroutines
import time:       605 |        605 |                 contextvars
import time:       738 |        738 |                 asyncio.format_helpers
import time:       652 |        652 |                   asyncio.base_futures
import time:       765 |        765 |                   asyncio.exceptions
import time:       713 |        713 |                   asyncio.base_tasks
import time:      1360 |       3488 |                 _asyncio
import time:      1295 |       6125 |               asyncio.events
import time:       861 |        861 |               asyncio.futures
import time:       916 |        916 |               asyncio.protocols
import time:      1117 |       1117 |                 asyncio.transports
import time:       584 |        584 |                 asyncio.log
import time:      4060 |       5760 |               asyncio.sslproto
import time:       468 |        468 |                   asyncio.mixins
import time:       920 |       1388 |                 asyncio.locks
import time:       663 |        663 |                   asyncio.queues
import time:       838 |        838 |                   asyncio.timeouts
import time:      1067 |       2567 |                 asyncio.tasks
import time:       886 |       4840 |               asyncio.staggered
import time:       653 |        653 |               asyncio.trsock
import time:      2405 |      46789 |             asyncio.base_events
import time:      1936 |       1936 |             asyncio.graph
import time:       718 |        718 |             asyncio.runners
import time:       763 |        763 |             asyncio.streams
import time:       941 |        941 |             asyncio.subprocess
import time:       870 |        870 |             asyncio.taskgroups
import time:       797 |        797 |             asyncio.threads
import time:      1826 |       1826 |               _overlapped
import time:      1249 |       1249 |               asyncio.base_subprocess
import time:      1652 |       1652 |               asyncio.proactor_events
import time:       864 |        864 |                   select
import time:      1655 |       2519 |                 selectors
import time:      1936 |       4455 |               asyncio.selector_events
import time:       173 |        173 |                     zlib
import time:      1170 |       1170 |                         compression
import time:      2346 |       3515 |                       compression._common
import time:      1561 |       1561 |                       compression._common._streams
import time:       828 |        828 |                       _bz2
import time:      1450 |       7354 |                     bz2
import time:       721 |        721 |                       _lzma
import time:       998 |       1719 |                     lzma
import time:       876 |        876 |                       _zstd
import time:      1115 |       1115 |                       compression.zstd._zstdfile
import time:      1812 |       3802 |                     compression.zstd
import time:      1902 |      14949 |                   shutil
import time:        81 |         81 |                       _bisect
import time:       973 |       1054 |                     bisect
import time:        81 |         81 |                     _random
import time:      1480 |       2614 |                   random
import time:      1407 |      18969 |                 tempfile
import time:      1146 |      20114 |               asyncio.windows_utils
import time:      2510 |      31804 |             asyncio.windows_events
import time:      1570 |      86184 |           asyncio
import time:       141 |      86324 |         asyncio.queues
import time:       945 |      87344 |       asyncutils._internal.compat
import time:      1356 |       1356 |         gettext
import time:      3374 |       4729 |       argparse
import time:      2121 |      94893 |     asyncutils._internal.parsed
import time:      3594 |       3594 |         _queue
import time:      2095 |       5689 |       queue
import time:      1537 |       7226 |     concurrent.futures.thread
import time:      1913 |     140447 |   asyncutils.config
import time:      1289 |       1289 |     pprint
import time:      3599 |       4887 |   asyncutils.context
import time:      1231 |       1231 |   asyncutils._internal.running_console
import time:      2257 |     148821 | asyncutils._internal.initialize
import time:      1075 |       1075 | asyncutils.base
import time:       731 |        731 |     _pyrepl
import time:       650 |        650 |     code
import time:      3425 |       4805 |   _pyrepl.console
import time:       121 |        121 |   gc
import time:       448 |        448 |           readline
import time:      1159 |       1607 |         rlcompleter
import time:      1078 |       1078 |           _pyrepl.trace
import time:      4281 |       5358 |         _pyrepl.commands
import time:      4961 |       4961 |             unicodedata
import time:      2662 |       7623 |           _pyrepl.input
import time:        83 |         83 |                 _typing
import time:      6839 |       6921 |               typing
import time:      1109 |       1109 |               _pyrepl.types
import time:      2977 |      11006 |             _pyrepl.utils
import time:      4216 |      15222 |           _pyrepl.reader
import time:      3947 |      26791 |         _pyrepl.historical_reader
import time:     20022 |      20022 |         _pyrepl.completing_reader
import time:      4461 |       4461 |           pkgutil
import time:     17893 |      22354 |         _pyrepl._module_completer
import time:      4596 |       4596 |             _ctypes
import time:      1352 |       1352 |             ctypes._endian
import time:      2465 |       8413 |           ctypes
import time:      1163 |       1163 |             ctypes._layout
import time:      2208 |       3371 |           ctypes.wintypes
import time:      6887 |       6887 |               _pyrepl.keymap
import time:      5343 |      12230 |             _pyrepl.base_eventqueue
import time:      8972 |      21201 |           _pyrepl.windows_eventqueue
import time:      8469 |      41452 |         _pyrepl.windows_console
import time:     16570 |     134150 |       _pyrepl.readline
import time:       213 |        213 |         termios
import time:      1637 |       1849 |       _pyrepl.unix_console
import time:      2163 |     138161 |     _pyrepl.simple_interact
import time:      4422 |     142583 |   _pyrepl.main
import time:     48480 |     195988 | asyncutils.console
import time:       278 |        278 | asyncutils.
<My console banner>
import time:      1186 |       1186 |   readline
import time:      1349 |       1349 |   _wmi
import time:   -405692 |       3528 | platform

The value for the platform module is somehow negative! I reran it immediately after discovering this, with no changes to my code, and the issue disappeared.

Also, there is another strange entry in the table:

import time:       278 |        278 | asyncutils.

'asyncutils.' is definitely not a module name, since it has a trailing dot. I can find no value in sys.modules corresponding to 'asyncutils.'.

I tested with another REPL similar to mine (namely the asyncio REPL) but encountered no such anomaly. However, I think it improbable that my library would mess up the output of python -X importtime to this extent.

CPython versions tested on:

3.14

Operating systems tested on:

Windows

[jonathandung]

I understand that multi-threaded applications may break the output, but my REPL is exactly as multi-threaded as asyncio's (one main thread vs one REPL thread)

[ZeroIntensity]

I couldn't reproduce this. This is likely just due to jitter in your system's clock. (platform in specific is particularly susceptible to this because the import is so fast.)

'asyncutils.' is definitely not a module name, since it has a trailing dot. I can find no value in sys.modules corresponding to 'asyncutils.'.

Do you have an empty string in your __all__ somewhere? That could trigger it. You could also trigger it by manually doing something like __import__("asyncutils", fromlist=[""]), but the former seems more likely.

[jonathandung]

Thank you for the quick response. I do happen to use __import__ with fromlist=('',), but definitely not for 'asyncutils', because it is not a submodule. There is also no empty string in my __all__.

[picnixz]

I do happen to use import with fromlist=('',),

Usually, you should avoid this.

import time: -405692 | 3528 | platform

This likely means that we failed to get the original time:

cpython/Python/import.c

Lines 4138 to 4141 in 836fbda

	fprintf(stderr, "import time: %9ld | %10ld | %*s%s\n",
	(long)_PyTime_AsMicroseconds(cum - accumulated, _PyTime_ROUND_CEILING),
	(long)_PyTime_AsMicroseconds(cum, _PyTime_ROUND_CEILING),
	import_level*2, "", PyUnicode_AsUTF8(abs_name));

Note that PyTime_PerfCounterRaw is expected to behave like time.perf_counter but time.perf_counter, on CPython at least, is meant to be monotonic, so I don't know how we went backwards:

Similar to PyTime_PerfCounter(), but don’t set an exception on error and don’t require an attached thread state.

[picnixz]

The issue with asyncutils. is concerning though. It's likely because fromlist=('',).

fromlist=('',), but definitely not for 'asyncutils'

What is the call of __import__ you're using? It may mean that we use a stale entry name somewhere.