How to speed up Python application startup time

I hear pipenv 9.0.2 is released with major startup time improvement.

I tried it soon and I didn't feel it's fast. So I investigated it with Python 3.7's new feature.

In this article, I introduce the feature and how to use it.

---

Startup time ≒ import time

For example, execution time of pipenv -h is much larger than time to show help message.

Generally speaking, when application starts, there are some startup process like loading environment variables or config files.

In case of Python application, importing module takes most of startup time. For example, pipenv --version took about 800ms and import pipenv took 700ms.

$ time local/py37/bin/python3 -c 'import pipenv'

real    0m0.696s
user    0m0.648s
sys     0m0.048s

$ time local/py37/bin/pipenv --version
pipenv, version 9.0.3

real    0m0.812s
user    0m0.761s
sys     0m0.052s

Show import time for modules

Python 3.7 has new feature to show time for importing modules.

This feature is enabled with -X importtime option or PYTHONPROFILEIMPORTTIME environment variable.

For example, you can profile import time of pipenv by

python3.7 -X importtime -c 'import pipenv' 2> pipenv-imports

or

PYTHONPROFILEIMPORTTIME=1 pipenv --version 2>pipenv-imports

Here is example output of pipenv --version

Investigating import time

At last of the output, you can see these lines:

import time: self [us] | cumulative | imported package
...
import time:      3246 |     578972 |   pipenv.cli
import time:       507 |     579479 | pipenv

In last line, 579479 means import pipenv took 579 479us.

While importing pipenv, many other modules are imported. From above example, you can see pipenv imports pipenv.cli. Subimports are indented with 2 spaces.

See last line again. 507 means only 507us was took when running pipenv module. 579 479 - 507 = 578 972us is used for subimports.

Finding slow part

Let's find slow subtree from the output. I selected some lines.

import time: self [us] | cumulative | imported package
...
import time:     86500 |     179327 | pkg_resources
...
import time:       385 |     236655 |             IPython
import time:        22 |     236677 |           IPython.core
import time:        26 |     236703 |         IPython.core.magic
import time:       978 |     237680 |       dotenv.ipython
import time:       199 |     239032 |     dotenv
...
...
import time:      3246 |     578972 |   pipenv.cli
import time:       507 |     579479 | pipenv

pkg_resources

As you can see, importing pkg_resources is slow.
And surprisingly, pkg_resources is not indented; it's not subimport of pipenv.

It means pkg_resources is imported by pipenv script, not module.

$ cat local/py37/bin/pipenv
#!/home/inada-n/local/py37/bin/python3.7
# EASY-INSTALL-ENTRY-SCRIPT: 'pipenv==9.0.3','console_scripts','pipenv'
__requires__ = 'pipenv==9.0.3'
import re
import sys
from pkg_resources import load_entry_point

if __name__ == '__main__':
    sys.argv[0] = re.sub(r'(-script\.pyw?|\.exe)?$', '', sys.argv[0])
    sys.exit(
        load_entry_point('pipenv==9.0.3', 'console_scripts', 'pipenv')()
    )

Bad news: Importing pkg_resources is slow. It's known issue and it's difficult to fix without breaking backward compatibility.

Good news: you can avoid importing pkg_resources!

$ local/py37/bin/pip install wheel
$ local/py37/bin/pip install -U --force-reinstall pipenv
$ time local/py37/bin/pipenv --version
pipenv, version 9.0.3

real    0m0.704s
user    0m0.653s
sys     0m0.052s

When wheel is installed, pip builds wheel and install from it.

Installing from wheel (.whl) and from source package (.tar.gz) are different process.
When installing from wheel, pkg_resources is not used in script:

$ cat local/py37/bin/pipenv
#!/home/inada-n/local/py37/bin/python3.7

# -*- coding: utf-8 -*-
import re
import sys

from pipenv import cli

if __name__ == '__main__':
    sys.argv[0] = re.sub(r'(-script\.pyw?|\.exe)?$', '', sys.argv[0])
    sys.exit(cli())

IPython

See next part.

import time:       385 |     236655 |             IPython
import time:        22 |     236677 |           IPython.core
import time:        26 |     236703 |         IPython.core.magic
import time:       978 |     237680 |       dotenv.ipython
import time:       199 |     239032 |     dotenv

pipenv imports dotenv, dotenv imports dotenv.ipython, and it imports IPython.

That's why pipenv starts slow on my environment; I have IPython installed.

But why IPython is imported? I read dotenv source and I found it's for IPython's extension.

Surely, pipenv and many dotenv users don't use IPython extension.
I made pull request to dotenv which make importing IPython on demand.

And since pipenv has own copy of dotenv, I made pull request to pipenv which removes dotenv.ipython completely.

Conclusion

I can reduce time for pipenv --version from 800ms to 500ms.

$ time local/py37/bin/pipenv --version
pipenv, version 9.0.3

real    0m0.503s
user    0m0.463s
sys     0m0.040s

Import time profiling is very nice way to investigating and optimize application startup time.

Comments

[rhymes]

Great work Inada!

[Dan Ryan]

Thanks for putting this article together and most importantly, thanks for contributing back to the project!