[Python] プログラムの実行パフォーマンスを計測する

こんにちは、@yoheiMuneです。
今日はPythonプログラムにおける、処理時間の計測やメモリ使用量のチェックなど、パフォーマンスチューニングを行うための調査方法をブログに書きたいと思います。

目次

サンプルコード

今回のサンプルコードは、以下のリポジトリにありますので、必要あればご参照ください。

https://github.com/yoheiMune/python-playground/tree/master/38_performance

timeコマンドを使ったお手軽計測

MacやLinux限定ですが、最もお手軽な方法はtimeコマンドを使うことです。以下のように、スクリプトの実行時間を計測できます。

$ time python3 perf1.py

# real  0m0.240s
# user  0m0.198s
# sys   0m0.032s

それぞれの意味は以下の通りです。

real:
    実際にかかった時間
user:
    プログラムが使った時間
sys:
    システムコールで使った時間

基本的にはrealやuserを確認して、実行時間を把握します。お手軽なのでよく使います。

datetimeモジュールを使って、プログラム内で計測する

プログラム内で時間を計測することもできます。datetime.now()で現在時刻のタイムスタンプを取得できるので、開始前と後でタイムスタンプの違いを取得し、それを経過時間とします。

以下では、Timerというクラスをコンテキストマネージャー（with句）で使うことで、実行時間を計測できるように実装しています。

from datetime import datetime

# 実行時間を計測するためのユーティリティ
class Timer(object):
    def __enter__(self):
        self.start = datetime.now()
    def __exit__(self, *exc):
        diff = (datetime.now() - self.start).microseconds / 1000
        print("time: {}ms".format(diff))

# コンテキストマネージャーとして使うことで、実行時間を計測する。
with Timer():
    arr = []
    for i in range(10000000):
        arr.append(i)

以下のように実行します。

$ python3 perf2.py

# time: 637.091ms

これも、バッチの処理時間の表示などで便利に使えます。

行ごとの処理時間を取得する

上記2点を用いることで、プログラム全体の実行時間を計測することができます。まずは全体の実行時間を把握することが大切ですが、問題がある（=時間がかかりすぎている）場合にどこを改善すれば良いのかは、もう少し詳しく調査を行う必要があります。

ここでは、行ごとの処理時間を取得する方法を紹介します。line_profilerというプロファイリングツールを利用します。

インストール

インストールはpip経由で簡単に行うことができます。

$ pip3 install -U line_profiler

計測対象プログラム

今回計測するプログラムは、以下とします。計測対象に@profileデコレータを付与しておきます。

from urllib.request import urlopen

# 計測対象の目印として「@profile」をつける
@profile
def get_images():
    images = []
    for index in range(500, 510):
        with urlopen("http://www.yoheim.net/image/{}.jpg".format(index)) as res:
            images.append(res.read())
    return images

images = get_images()

処理内容は、僕のブログから10枚画像を取得して結果を配列に格納する、という処理になります。

実行する

pipインストールでkernprofコマンドが使えるようになっているので、それを使って計測を行います。

$ kernprof -l -v perf3.py

-lはline-by-lineで計測を行うように指示し、-vは結果をコンソールに出力するように指示しています。オプションの詳細はkernprof --helpで確認できます。

検証する

上記を実行すると、以下のような出力結果を得ることができます。

$ kernprof -l -v perf3.py 
Wrote profile results to perf3.py.lprof
Timer unit: 1e-06 s

Total time: 0.874731 s
File: perf3.py
Function: get_images at line 12

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    12                                           @profile
    13                                           def get_images():
    14         1            4      4.0      0.0      images = []
    15        11           35      3.2      0.0      for index in range(500, 510):
    16        10       282544  28254.4     32.3          with urlopen("http://www.yoheim.net/image/{}.jpg".format(index)) as res:
    17        10       592147  59214.7     67.7              images.append(res.read())
    18         1            1      1.0      0.0      return images

それぞれの列の意味は以下の通りです。

Line #:
    ファイルの行数
Hits:
    その行が実行された回数
Time:
    その行が実行された時間の合計（単位は、「Timer unit」で指定されています、ここでは1e-06s）
Per Hit:
    その行が実行された時間の1回あたりの平均
% Time:
    合計時間に占める割合
Line Contents:
    具体的なプログラム内容

ここではimages.append(res.read())が全体の67%を占めており、重たい処理であることがわかります。そして必要があればここの処理を改善していきます。

メモリの使用量を調べる

上記ではステップごとの処理時間を調べましたが、メモリの使用量を調べることもできます。どこでメモリが使われているのかを把握し、そこでのメモリ使用量を抑えることで、プログラムのパフォーマンスを改善することができます。

メモリの使用量調査には、memory_profilerを利用します。

インストール

pip経由で簡単にインストールすることができます。

$ pip3 install -U memory_profiler

また、計測速度を早めるためにpsutilも一緒にインストールします（無くても動きます）。

$ pip3 install -U psutil

計測対象のプログラム

ここでは、line_profilerで計測した関数を計測したいと思います。

from urllib.request import urlopen

# 計測対象の目印として「@profile」をつける
@profile
def get_images():
    images = []
    for index in range(500, 510):
        with urlopen("http://www.yoheim.net/image/{}.jpg".format(index)) as res:
            images.append(res.read())
    return images

images = get_images()

実行する

計測の実行は、以下のように行います。

$ python3 -m memory_profiler perf4.py

検証する

実行結果は以下のように表示がされ、メモリの使用量を調べることができます。

Filename: perf4.py

Line #    Mem usage    Increment   Line Contents
================================================
    12   38.965 MiB    0.000 MiB   @profile
    13                             def get_images():
    14   38.965 MiB    0.000 MiB       images = []
    15   44.242 MiB    5.277 MiB       for index in range(500, 510):
    16   43.980 MiB   -0.262 MiB           with urlopen("http://www.yoheim.net/image/{}.jpg".format(index)) as res:
    17   44.242 MiB    0.262 MiB               images.append(res.read())
    18   44.242 MiB    0.000 MiB       return images

それぞれの列の内容は、以下の通りです。

Line #:
    ファイルの行数

Mem usage:
    該当行を実行した後の、Pythonインタプリタが消費しているメモリ量

Increment:
    1つ前の行とのメモリ使用量の差分

Line Contents:
    具体的なプログラムの内容

このようにどこでメモリを消費しているのかを把握することができ、メモリ使用量を抑えるように修正することで、高速なプログラムに変更することができます（メモリの割り当てには時間がかかるため、それを避けるのがベターです）。

参考資料

今回の実装は、以下の内容を参照しました。ありがとうございます。

Pythonスクリプトのパフォーマンス計測ガイド

rkern/line_profiler | Github

fabianp/memory_profiler | Github

最後に

スクレイピングの処理やバッチ処理を書いていると、パフォーマンスが出ない時もちらほら。そんな時に改善するためのヒントにも、今回のようなプロファイリングができるようになると素敵です。ぜひ活用していきたいと思います。

最後になりますが本ブログでは、Python・Go言語・Linux・フロントエンド・Node.js・インフラ・開発環境・Swift・Java・機械学習など雑多に情報発信をしていきます。自分の第2の脳にすべく、情報をブログに貯めています。気になった方は、本ブログのRSSやTwitterをフォローして頂けると幸いです ^ ^。

最後までご覧頂きましてありがとうございました！