This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: Regression in time to import a module
Type: performance Stage: resolved
Components: Versions: Python 3.6, Python 3.5
process
Status: closed Resolution: works for me
Dependencies: Superseder:
Assigned To: Nosy List: barry, brett.cannon, eric.snow, ncoghlan, serhiy.storchaka, terry.reedy, vstinner
Priority: normal Keywords:

Created on 2015-09-18 06:10 by serhiy.storchaka, last changed 2022-04-11 14:58 by admin. This issue is now closed.

Messages (12)
msg250941 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2015-09-18 06:10
There are regressions in import time in 3.5 and 3.6.

$ for i in `seq 5`; do ./python -I -m timeit -n1 -r1 "import enum"; done

Python 3.4:
1 loops, best of 1: 3.45 msec per loop
1 loops, best of 1: 3.43 msec per loop
1 loops, best of 1: 3.55 msec per loop
1 loops, best of 1: 3.54 msec per loop
1 loops, best of 1: 3.42 msec per loop

Python 3.5:
1 loops, best of 1: 4.38 msec per loop
1 loops, best of 1: 4.31 msec per loop
1 loops, best of 1: 4.32 msec per loop
1 loops, best of 1: 4.32 msec per loop
1 loops, best of 1: 4.4 msec per loop

Python 3.6:
1 loops, best of 1: 20.2 msec per loop
1 loops, best of 1: 20.2 msec per loop
1 loops, best of 1: 22 msec per loop
1 loops, best of 1: 20.3 msec per loop
1 loops, best of 1: 20.4 msec per loop


$ for i in `seq 5`; do ./python -I -m timeit -n1 -r1 -s "import sys; sys.modules.clear()" -- "import enum"; done

Python 3.4:
1 loops, best of 1: 29.5 msec per loop
1 loops, best of 1: 29.3 msec per loop
1 loops, best of 1: 30 msec per loop
1 loops, best of 1: 28.9 msec per loop
1 loops, best of 1: 29.2 msec per loop

Python 3.5:
1 loops, best of 1: 43.8 msec per loop
1 loops, best of 1: 44 msec per loop
1 loops, best of 1: 43.5 msec per loop
1 loops, best of 1: 43.1 msec per loop
1 loops, best of 1: 43.8 msec per loop

Python 3.6:
1 loops, best of 1: 59.8 msec per loop
1 loops, best of 1: 59.1 msec per loop
1 loops, best of 1: 58.8 msec per loop
1 loops, best of 1: 58.6 msec per loop
1 loops, best of 1: 61.9 msec per loop


And even in importing already imported and cached module there is small regression.
$ for i in `seq 5`; do ./python -I -m timeit "import enum"; done

Python 3.4:
100000 loops, best of 3: 3.04 usec per loop
100000 loops, best of 3: 3.07 usec per loop
100000 loops, best of 3: 3.08 usec per loop
100000 loops, best of 3: 3.11 usec per loop
100000 loops, best of 3: 3.04 usec per loop

Python 3.5:
100000 loops, best of 3: 3.27 usec per loop
100000 loops, best of 3: 3.22 usec per loop
100000 loops, best of 3: 3.18 usec per loop
100000 loops, best of 3: 3.28 usec per loop
100000 loops, best of 3: 3.17 usec per loop

Python 3.6:
100000 loops, best of 3: 3.29 usec per loop
100000 loops, best of 3: 3.26 usec per loop
100000 loops, best of 3: 3.34 usec per loop
100000 loops, best of 3: 3.35 usec per loop
100000 loops, best of 3: 3.35 usec per loop
msg251008 - (view) Author: Brett Cannon (brett.cannon) * (Python committer) Date: 2015-09-18 15:35
I don't know how much of this is directly importlib's fault, at least in the 3.5 -> 3.6 case, as very little has changed in the bootstrap code since 3.6 started: https://hg.python.org/cpython/log/default/Lib/importlib/_bootstrap.py and https://hg.python.org/cpython/log/default/Lib/importlib/_bootstrap_external.py and https://hg.python.org/cpython/log/default/Python/import.c .
msg251009 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-09-18 16:10
Even if Python 3.5 startup is slower than Python 3.4 startup, I'm more concerned by Python 3.6! What happens in Python 3.6? Are you sure that all binaries were compiled in release mode?

Why do you import enum? The bare minimum is "pass" :-)
msg251010 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2015-09-18 16:40
This is not startup time, this is import time. All binaries were compiled in release mode. The regression is reproducible with other modules.

$ for i in `seq 5`; do ./python -I -m timeit -n1 -r1 "import zipfile"; done

Python 3.4:
1 loops, best of 1: 46 msec per loop
1 loops, best of 1: 45.3 msec per loop
1 loops, best of 1: 45.9 msec per loop
1 loops, best of 1: 45.1 msec per loop
1 loops, best of 1: 45.3 msec per loop

Python 3.5:
1 loops, best of 1: 49.1 msec per loop
1 loops, best of 1: 49.9 msec per loop
1 loops, best of 1: 50 msec per loop
1 loops, best of 1: 49.9 msec per loop
1 loops, best of 1: 53.7 msec per loop

Python 3.6:
1 loops, best of 1: 66.3 msec per loop
1 loops, best of 1: 64.2 msec per loop
1 loops, best of 1: 64.6 msec per loop
1 loops, best of 1: 65.1 msec per loop
1 loops, best of 1: 64.2 msec per loop
msg251032 - (view) Author: Brett Cannon (brett.cannon) * (Python committer) Date: 2015-09-18 21:58
It should also be mentioned that startup time from 3.4 to default has not been affected according to Intel's daily benchmark run which is usually the most obvious place you see import performance issues:

normal_startup    0.63661%          0.39540%          0.45931%          5.22018%
msg251045 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2015-09-19 00:28
Clarify title; regression is not in 'import time'. I am working on timing the import of Lib/*.py on windows.  I already discovered that unix-only crypt is present on windows (but should not be).
msg251057 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2015-09-19 06:44
I did not find any significant different between 3.4 and 3.5 on Windows running the following:

import os, time
from importlib import import_module

files = os.listdir("C:/Programs/Python34/Lib")
excludes = {'antigravity.py', 'compileall.py', 'crypt.py', 'pty.py',
            'this.py', 'tty.py', '__phello__.foo.py'}
start = time.monotonic()
for name in files:
    if name.endswith('.py') and name not in excludes:
        try:
            import_module(name[:-3])
        except:
            print(name)
print(time.monotonic()-start)

Other than a couple of outliers, the time was consintly about .29 seconds with both 3.4 and 3.5:
  F:\Python\dev>py -3.x  c:/programs/python34/tem.py
The 3.5 run is a bit odd since it runs both 3.4 code and 3.5 code, but there were no extra exceptions once I added the needed exclusions (pyt and tty are also unix only) for 3.4.  The same code runs equally faster with Idle (.17 seconds), but that must be because Idle has already imported so many more /Lib modules (not including idlelib/*) than python itself.
msg251303 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-09-22 10:27
I tested on Linux.

(1) for i in `seq 5`; do ./python -I -m timeit -n1 -r1 -s "import sys; sys.modules.clear()" -- "import enum"; done

(shortest timing)

Python 3.4: 6.93 msec
Python 3.6: 7.05 msec (+2%)


(2) for i in `seq 5`; do ./python -I -m timeit "import enum"; done

Python 3.4: 0.331 usec
Python 3.6: 0.341 usec (+%3)

These numbers are nanoseconds, it's too short to run a real benchmark.


(3) for i in `seq 5`; do ./python -I -m timeit -n1 -r1 "import enum"; done

Python 3.4: 801 usec
Python 3.6: 774 usec (-3%)


Sorry, I don't see major differences like you showed. Can you explain exactly how to reproduce them? Exact Python version? OS?

I used the development branches (branch 3.4 and branch default).
msg251349 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2015-09-22 21:49
I just have rebuilt my Python's in development brances after made distclean to avoid possible effects of incremental building, and got the same results.

(1) for i in `seq 5`; do ./python -I -m timeit -n1 -r1 -s "import sys; sys.modules.clear()" -- "import enum"; done

Python 3.4: 29 msec
Python 3.5: 43.4 msec (+50%)
Python 3.6: 44.4 msec (+2%, +53%)


(2) for i in `seq 5`; do ./python -I -m timeit "import enum"; done

Python 3.4: 3.02 usec
Python 3.5: 3.14 usec (+4%)
Python 3.6: 3.34 usec (+6%, +10%)


(3) for i in `seq 5`; do ./python -I -m timeit -n1 -r1 "import enum"; done

Python 3.4: 3.49 msec
Python 3.5: 4.19 msec (+20%)
Python 3.6: 4.45 msec (+6%, +28%)


32-bit Ubuntu 14.04, Linux 3.16, gcc 4.8.4, Intel(R) Atom(TM) CPU N570   @ 1.66GH.
msg253054 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-10-15 16:15
Importing a module looks slow to me. Importing a module which is a an *empty* .py file takes ~160 us.

$ python3 -I -m timeit -s "open('slow.py', 'wb').close(); import sys; import slow" "del sys.modules['slow']; import slow"
10000 loops, best of 3: 156 usec per loop

The difference betwen Python 3.4 and 3.5 is that enum.py imports indirectly more modules. The following two imports were added to types.py in Python 3.5:

import functools as _functools         
import collections.abc as _collections_abc
msg253055 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-10-15 16:16
$ 3.4/python -c "import sys; sys.modules.clear(); import enum; print(len(sys.modules))"
18

$ 3.5/python -c "import sys; sys.modules.clear(); import enum; print(len(sys.modules))"
22
msg253062 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2015-10-15 18:36
Yes, importing 4 additional modules can be a cause of the slowdown. Thanks Victor.
History
Date User Action Args
2022-04-11 14:58:21adminsetgithub: 69346
2015-10-15 18:36:14serhiy.storchakasetstatus: open -> closed
resolution: works for me
messages: + msg253062

stage: resolved
2015-10-15 16:16:25vstinnersetmessages: + msg253055
2015-10-15 16:15:30vstinnersetmessages: + msg253054
2015-09-22 21:49:25serhiy.storchakasetmessages: + msg251349
2015-09-22 10:27:09vstinnersetmessages: + msg251303
2015-09-19 06:44:40terry.reedysetmessages: + msg251057
2015-09-19 00:28:09terry.reedysetnosy: + terry.reedy

messages: + msg251045
title: Import time regression -> Regression in time to import a module
2015-09-18 21:58:30brett.cannonsetmessages: + msg251032
2015-09-18 16:40:36serhiy.storchakasetmessages: + msg251010
2015-09-18 16:10:12vstinnersetmessages: + msg251009
2015-09-18 16:08:02vstinnersetnosy: + vstinner
2015-09-18 15:35:21brett.cannonsetmessages: + msg251008
2015-09-18 13:38:49barrysetnosy: + barry
2015-09-18 06:10:06serhiy.storchakacreate