DSAS開発者の部屋

pipenv 9.0.2 のリリースでCLIの大幅な高速化をしたというアナウンスを見かけました。

Just released Pipenv v9.0.2, which includes massive CLI speedups! https://t.co/AGD8Hkq1EG

— Kenneth Reitz 🐍 (@kennethreitz) 2018年1月16日

興味を持ってすぐに試してみたのですが、あまり速く感じられませんでした。そこで Python 3.7 の新機能を使って速度を調査することにしました。

この記事ではその新機能と実際の使い方を紹介します。

起動時間 ≒ import時間

pipenv -h のようなコマンドの実行時間は、実際にヘルプメッセージを表示するための時間よりもずっと長くなります。

アプリケーションが起動するときには、設定ファイルの読み込みなど一定の処理が必要になるものです。

しかし、Pythonアプリケーションの場合、モジュールのインポートが起動時間の殆どをしめる事が多いです。

たとえば私の環境では pipenv --version は 800ms かかったのですが、そのうち 700ms は import pipenv に使われていました。

$ 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

モジュールのimportにかかった時間を表示する

Python 3.7 ではモジュールのimportにかかった時間を表示する機能が追加されました。

この機能は -X importtime オプションか、 PYTHONPROFILEIMPORTTIME=1 と環境変数に設定することで有効になります。

たとえば pipenv を調査したい時は次の２つの方法があります。

$ python3.7 -X importtime -c 'import pipenv' 2> pipenv-imports
または
$ PYTHONPROFILEIMPORTTIME=1 pipenv --version 2>pipenv-imports

前者は import pipenv だけを調査し、後者は pipenv コマンド実行中の全ての import を調査するという違いがあります。

後者の出力結果の例が こちら です。

import時間を解析する

この出力結果の最後の部分を見てみます。

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

最後の行の右側の 579479 は、 import pipenv にトータルで 579479us かかったことを意味しています。

pipenv を import する間に、たくさんの他のモジュールが import されます。上の例で言えば、 pipenv は pipenv.cli を import しています。(サブ import は２スペースでインデントされます)

最後の行の左側の 507 は、 pipenv モジュール単体の import (モジュールのグローバルの実行を含む) にたった 507us しか掛かっていないことを意味しています。579 479 - 507 = 578 972us がサブimportに掛かっています。

遅い部分を見つける

先程の出力から、時間を使っている部分木を探しましょう。幾つかの行を抜粋します。

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

最初に見つけたのが pkg_resources です。注目してほしいのは、このモジュールがインデントされていないことです。つまり、 pipenv モジュールから間接的に import されているわけではないのです。

実際、 pkg_resources は pipenv スクリプト から import されていました。

$ 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')()
    )

pkg_resources の import が遅いのは既知の問題で、後方互換性を壊さずに修正するのが難しい問題です。

しかし、 pkg_resources の import は回避することができます。

$ 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

これで、 pipenv --version コマンドの実行時間はほとんど import pipenv の時間と等しくなりました。

wheel がインストールされている時、 pip はソースパッケージ (.tar.gz など) をダウンロードしてきても、一旦 wheel (.whl) をビルドして、 wheel からインストールします。 そして wheel からインストールする時とソースパッケージからインストールする時でスクリプトを生成する処理が異なり、 wheel からインストールした場合には pkg_resources が使われないのです。

$ 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())

つまり、 wheel をインストールしておけば、ソースパッケージしか配布していないツールをインストールする時にかかる余計な時間（私の環境ではおおよそ100ms程度）を回避することができます。

IPython

次に見つけた遅い部分はここです。

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 が dotenv を import して、 dotenv が dotenv.ipython を、 dotenv.ipython が IPython を import しています。

これが、私の環境 (IPython がインストールされていた) で pipenv の起動が遅く感じた最大の理由のようです。

しかしなぜ IPython が import されるのでしょう？ dotenv のソースを読んでみた所、どうやら IPython extension のためようです。

もちろん、 pipenv やその他の多くの dotenv のユースケースでは IPython extension は使いません。なので dotenv がオンデマンドで IPython を import するような プルリクエスト を送っておきました。

また、 pipenv は dotenv にパッチを当てた独自コピーを埋め込んで利用しているので、そこから dotenv.ipython を取り除く プルリクエスト も送っておきました。

まとめ

pipenv --version の実行時間を 800ms から 500ms に削減することができました。

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

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

このように、Python 3.7 の import 時間プロファイルは、CLIアプリケーションの起動時間を高速化するためにとても便利です。

@methane