TECHNOLOGY

IPythonで実行時間を測定＆プロファイリングする方法

Pythonは、コードの書き方によって実行速度が大きく変わることがよくあります。特にビッグデータを扱う場合、わずかな処理の違いが全体の実行時間に大きな影響を与えることもあります。このため、手軽に処理時間を計測し、効率的なコードを書くノウハウを蓄積しておくことは、開発や分析業務において非常に役立ちます。

また、アプリケーションのパフォーマンス改善において、最も時間がかかっている処理を特定することは欠かせません。適切なプロファイリングを行うことで、ボトルネックを見つけ、実行速度を大幅に向上させることが可能になります。

本記事では、IPythonを活用してコードの実行時間を手軽に測定する方法やプロファイリングによるボトルネックの特定についてご紹介します。

目次

IPythonのインストール

IPython（Interactive Python）は、Pythonの対話型シェルの拡張版で、データサイエンスや開発の現場で広く利用されています。

特徴としてはTabを使ったオートコンプリート（変数やメソッドの候補を出す機能）や便利なヘルプ機能、マジックコマンドがあります。

IPythonをインストールするには、以下のコマンドを実行します。

pip install ipython

インストール後、ターミナルやコマンドプロンプトで次のコマンドを入力すると起動できます。

ipython

VS Codeの場合には、Ctrl+@でターミナルを開いてIPythonを実行してテストしながら、エディタでコードを書くようなスタイルも可能です。

実行時間の計測（コードブロック）

IPythonでは、コードの実行時間を測定するために%timeと%timeitの2つのマジックコマンドが用意されています。

マジックコマンド説明
%time単一のコードブロックの実行時間を一度だけ測定するコマンドです。
%timeit単一のコードブロックを何度も実行して統計的に平均実行時間を測定します。計算誤差を減らし、より正確な実行時間を得ることができます。

IPython上で実際に試してみます。%timeの場合には次のようになります。

In [1]: %time sum(range(1000000))
CPU times: total: 15.6 ms
Wall time: 10.7 ms

CPU timesはプロセッサが計算に費やした時間、Wall timeは実際に経過した時間（ユーザーが体感する時間）です。

In [1]: %timeit sum(range(1000000))
10.6 ms ± 132 μs per loop (mean ± std. dev. of 7 runs, 100 loops each)

出力結果は、7回の試行を行い、各試行で100ループ実行しています。その結果、1回のループあたりの平均実行時間が10.6 msで、標準偏差が132 μs（ばらつきの範囲）であったことを意味しています。

これらのマジックコマンドは、関数にも使用できます。

In [1]: def sum_numbers(n):
   ...:     return sum(range(n))
   ...:

In [2]: %time sum_numbers(1000000)
CPU times: total: 15.6 ms
Wall time: 11.4 ms
Out[2]: 499999500000

In [3]: %timeit sum_numbers(1000000)
10.6 ms ± 158 μs per loop (mean ± std. dev. of 7 runs, 100 loops each)

実行時間の計測（スクリプト全体）

IPythonで%runコマンドを使うと、外部のスクリプト（test.pyなど）を実行できます。

スクリプトの実行時間を測る場合には、以下のようにします。

%time %run test.py

あるいは、

%timeit %run test.py

です。%timeitを使用する場合、スクリプトにprint文が含まれていると大量に出力されてしまいます。この場合には、スクリプトの中のprint文をあらかじめ無効化しておきます。

import sys
sys.stdout = None  # 出力を無効化

...

sys.stdout = sys.__stdout__  # 出力を元に戻す

%timeitには主なオプションとして次のものがあります。

オプション説明例
-n Nループ回数を指定%timeit -n 100 sum(range(1000))
-r R試行回数を指定%timeit -r 5 sum(range(1000))
-ttime.time()を使用%timeit -t sum(range(1000))
-p N表示桁数の指定%timeit -p 6 sum(range(1000))
-o結果を変数として保存result = %timeit -o sum(range(1000))

-oオプションについては、保存された結果resultを使って詳細情報を確認できます。

result = %timeit -o sum(range(1000))

print(result.average)  # 平均実行時間
print(result.best)  # 最速の実行時間
print(result.worst)  # 最も遅い実行時間
print(result.repeat)  # 試行回数
print(result.all_runs)  # 全試行の実行時間一覧

プロファイリング

プロファイリングは、プログラムの実行時間やメモリ使用量を詳細に分析し、どの部分に時間がかかって、どの関数がボトルネックになっているかを特定する手法です。

コードが遅いときに、どこが遅い原因になっているかが分かれば、パフォーマンスを改善するヒントになります。

プロファイリングを行うモジュールとして、cProfileがあります。cProfileは関数ごとの実行時間を詳細に測定できる標準ライブラリです。スクリプト内で使用する場合には、以下のように使います。

import cProfile

def slow_function(n):
    total = 0
    for i in range(n):
        total += i
    return total

def nest_function(n):
    slow_function(n)

profiler = cProfile.Profile()
profiler.enable()  # プロファイリング開始

nest_function(1000000)  

profiler.disable()  # プロファイリング終了
profiler.print_stats()  # 結果を表示

あるいは、単一の関数のプロファイリングを行う場合には、次の方法でもプロファイル可能です。

cProfile.run("nest_function(1000000)")

実行すると、以下のような結果が得られます。

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.237    0.237 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 contextlib.py:145(__exit__)
        1    0.000    0.000    0.000    0.000 history.py:1048(hold)
        1    0.000    0.000    0.000    0.000 history.py:999(_writeout_output_cache)
        1    0.000    0.000    0.237    0.237 test.py:11(nest_function)
        1    0.237    0.237    0.237    0.237 test.py:4(slow_function)
        1    0.000    0.000    0.000    0.000 threading.py:303(__enter__)
        1    0.000    0.000    0.000    0.000 threading.py:312(_release_save)

それぞれ、次の意味があります。

列名説明
ncalls呼び出された回数
tottime関数自体の実行時間
percall1回の呼び出しあたりの時間
cumtime累積実行時間（子関数の時間も含む）
filename:lineno(function)実行された関数のファイルと行番号

cumtimeは子関数の時間も含むことに注意が必要です。

IPythonでcProfileを使用するのは簡単で%prunを使用します。ここでは、%loadコマンドでtest.pyを読み込み、%prunで関数を指定してプロファイリングしています。

In [1]: %load test.py

In [2]: # %load test.py
    ...: def slow_function(n):
    ...:     total = 0
    ...:     for i in range(n):
    ...:         total += i
    ...:     return total
    ...:
    ...:
    ...: def nest_function(n):
    ...:     slow_function(n)
    ...:

In [3]: %prun nest_function(100000)
         5 function calls in 0.003 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.003    0.003    0.003    0.003 <ipython-input-35-e609752df08c>:2(slow_function)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.003    0.003 {built-in method builtins.exec}
        1    0.000    0.000    0.003    0.003 <ipython-input-35-e609752df08c>:9(nest_function)
        1    0.000    0.000    0.003    0.003 <string>:1(<module>)

上の例は関数１つに対して実行しましたが、スプリクト全体に対して実行することもできます。例えば、

def slow_function(n):
    total = 0
    for i in range(n):
        total += i
    return total

def nest_function(n):
    slow_function(n)

if __name__ == "__main__":
    nest_function(10000000)

に対して、IPython上で次のコマンドを打つとプロファイリングできます（test.pyはスクリプトのファイル名）。

%prun %run test.py

%prunにはソートなどの便利なオプションがあります。

オプション説明例
-l N出力をN行までにする%prun -l 5 %run test.py
-s tottime関数自体の処理時間順にソート%prun -l 5 -s tottime %run test.py
-s cumtime累積実行時間順にソート（子関数の時間も含む）%prun -l 5 -s cumtime nest_function(1000000)
-s ncalls関数の呼び出し回数順にソート%prun -l 5 -s ncalls %run test.py

ソートすることで、一番時間がかかっているプロセスを見つけやすくなります。

ラインプロファイリング

ラインプロファイリングは、Pythonのコードを関数単位ではなく、行単位でプロファイリングする方法です。ラインプロファイリングを使うと、関数内の「どの行」が時間を消費しているのかを正確に測定できます。

このために、line_profilerパッケージを使用します。

pip install line-profiler

まず、スクリプトに直接書き込んで、ラインプロファイルを行います。まず、スクリプトでラインプロファイルしたい関数に @profile をつけます。

@profile
def slow_function(n):
    total = 0
    for i in range(n):
        total += i
    return total

if __name__ == "__main__":
    slow_function(10000000)

そして、コマンドプロンプト上で、次のコマンドを実行します。

kernprof -l -v test.py

その結果、次のような結果が得られます。

Wrote profile results to test.py.lprof
Timer unit: 1e-06 s

Total time: 3.44857 s
File: test.py
Function: slow_function at line 1

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     1                                           @profile
     2                                           def slow_function(n):
     3         1          0.5      0.5      0.0      total = 0
     4  10000001    1731266.6      0.2     50.2      for i in range(n):
     5  10000000    1717297.8      0.2     49.8          total += i
     6         1          1.8      1.8      0.0      return total

IPython上の場合には、%lprunコマンドを使用します。

%lprun -f 関数名 関数名（引数）

IPython上で使用するには、%load_ext line_profiler（Pythonの）を実行した後に、%lprunを実行します。

%lprunを使う前にプロファイリングする関数が定義されている必要があるため、サンプルコードでは%loadを用いてスクリプトを読み込んでいます（%runでも可能です）。

In [1]: %load_ext line_profiler

In [2]: %load test.py

In [3]: # %load test.py
   ...: def slow_function(n):
   ...:     total = 0
   ...:     for i in range(n):
   ...:         total += i
   ...:     return total
   ...:

In [4]: %lprun -f slow_function slow_function(1000000)
Timer unit: 1e-07 s

Total time: 0.357325 s
File: <ipython-input-3-028f81fc0b15>
Function: slow_function at line 2

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     2                                           def slow_function(n):
     3         1          4.0      4.0      0.0      total = 0
     4   1000001    1813721.0      1.8     50.8      for i in range(n):
     5   1000000    1759509.0      1.8     49.2          total += i
     6         1         16.0     16.0      0.0      return total

まとめ

Python でコードの最適化を行う際、実行時間を測定し、ボトルネックを特定することが重要 です。
本記事では、IPython を活用した実行時間の測定とプロファイリング手法 について紹介しました。

  • %time / %timeit：処理の実行時間を素早く測定
  • %prun / cProfile：関数単位のプロファイリング
  • %lprun / line_profiler：関数内の 各行 の実行時間を測定
  • kernprof -l -v script.py：スクリプト全体の 行ごとの処理時間を分析

また、%lprun を使用する際は、%run や %load で関数をロードしておく必要がある ことに注意が必要です。

プロファイリングを活用し、コードのパフォーマンスを上げる参考になりましたら幸いです。

-TECHNOLOGY
-