Python で実行時間を計測したい。

ここでは 4 つの方法を紹介します。

項番 名称 説明
1 time
コマンド
スクリプト全体の時間
2 time
モジュール
スクリプトの一部の時間
自分が書いたコードのなかで
特定のコードの時間を計測したい時に使う。
3 cProfile
モジュール
スクリプトの一部の時間
遅い関数、メソッドを特定したい時に使う。
関数, メソッドごとに時間を計測してくれます。
4 timeit
モジュール
スクリプト全体の時間
正確な時間を計測したい時に使う。
ただし 2, 3 行のごく短いもののみ

1. Linux の time コマンド

自分が書いたコード全体の処理時間を測定したい時に使います。一番お手軽ですね。

$ time python script.py
real  0m0.647s
user  0m0.614s
sys   0m0.015s

2. Python の time モジュール

自分が書いたコードの中で、特定の箇所を測定したい時に使います。
16.3. time — 時刻データへのアクセスと変換

import time


start_time = time.time()

y = x*x

end_time = time.time()
execution_time = end_time - start_time
print(execution_time)

◯ 非推奨 time をデコレータを使って

デコレータを使って特定の関数、メソッドの実行時間だけ取得する方法です。自分も作ろうとしてしまいましたし、割とよく見かける書き方ですが、もしかしたら避けた方がいいかもしれません。

何故なら1つ目の理由は cProfile があるからです。2つ目の理由は、作り込もうとして結構泣かされました。特に 1. 再起呼び出し, 2. 複数の関数を同時に計測できるように対応しようとすると沼にハマります。結局途中で cProfile を見つけましたが。

Qiita | Pythonで処理の時間を計測する冴えた方法
Qiita | Pythonで実行時間を計測する方法 その1

3. cProfile モジュール

どこの処理で時間がかかっているかを調べたい時に使います。cProfile は、関数、メソッドごとに処理時間を提示してくれます。
27.4. Python プロファイラ

一見して複雑そうですが、使い方は簡単で、実行時間順にソートして、時間がかかっているものから順に処理を速くできないかを検討していくような流れになります。

◯ 使い方

$ # cumtime で sort
$ python -m cProfile -s cumtime myscript.py
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   130662    0.129    0.000    0.161    0.000 rectangle.py:1183(__and__)
     3455    0.125    0.000    0.320    0.000 rectangle.py:1065(_make_rectangle_list_by_removing_inclusion)
   292064    0.104    0.000    0.104    0.000 rectangle.py:1196(__le__)
     7388    0.067    0.000    0.181    0.000 rectangle.py:424(_stub_rectangle_list)
...


抑えておきたいポイントは、次の3つです。

  1. ncalls が呼び出された回数であること
  2. totime と cumtime の2つの時間があること
  3. totime と cumtime の違い

◯ 各項目の詳細

表. 各項目の説明(公式マニュアルからの抜粋して補足)
項目 説明
ncalls 呼び出し回数
tottime 与えられた関数に消費された合計時間 (sub-function の呼び出しで消費された時間は除外されています)
percall tottime を ncalls で割った値
cumtime この関数と全ての subfunction に消費された累積時間 (起動から終了まで)。
percall cumtime をプリミティブな呼び出し回数(再帰的に呼び出されていない呼び出し回数)で割った値
filename:lineno(function) その関数のファイル名、行番号、関数名


ncalls に 2 つの数字が表示される時があります。そんな時は、関数、メソッドが再帰的に呼び出されている時です。

最初の行に 2 つの数字がある場合 (たとえば 3/1) は、関数が再帰的に呼び出されたということです。2 つ目の数字はプリミティブな呼び出しの回数で、1 つ目の数字は総呼び出し回数です。関数が再帰的に呼び出されなかった場合、それらは同じ値で数字は 1 つしか表示されないことに留意してください。
27.4.2. かんたんユーザマニュアル


また、各項目の詳細は公式マニュアルにもありますが、実際のソースコードの docstring により詳細が記述されています。
https://github.com/python/cpython/blob/3.6/Lib/profile.py


◯ totime と cumtime の違いと対処の仕方

1. totime(Total time)

関数やメソッドの実行時間を引き抜いた時間です。自分で書いた for, while, if 文で書いたアルゴリズムが、どのくらい時間がかかっているかがわかります。呼び出した関数の処理時間は除かれます。

tottime を全て足し合わせると総実行時間になります。

総実行時間 = sum(all of tottime)


もし、tottime が大きかった場合、自分自身で書いたコードで遅いところが無いか検証します。

2. cumtime(Cumulative time)

呼び出した関数やメソッドの実行時間を含めた時間です。

例えば、以下のような 4 行の Pythonスクリプト sample.py があった場合、

# sample.py
func1()
func2()
func3()

次のような関係が成り立ちます。

総実行時間 = cumtime(func1) + cumtime(func2) + cumtime(func3)


もし、cumtime が大きかった場合、呼び出している関数、メソッドで処理時間が大きいものを探して改善策を検討します。実は Python は関数、メソッドの呼び出しコストが大きいので、呼び出している関数、メソッドをベタ書きするだけで速度が改善したりします。このあと、実際に関数とベタ書きした場合の処理速度を比較します。

用語: プロファイル

プログラムを動かして各関数の実行時間や呼ばれた回数を記載したものをプロファイルと言います。このプロファイルという言葉は各言語に共通です。Python に限定されません。 また、プロファイルを作成するツールを、プロファイラといいます。

プロファイル (profile) とは、
プログラムの各部分がどれだけ頻繁に呼ばれたか、そして実行にどれだけ時間がかかったかという統計情報です。

4. timeit モジュール

実行時間のベンチマークを測りたい時に使います。time モジュール, Profile モジュールに比べて、より正確な値を計測できます。
27.5. timeit — 小さなコード断片の実行時間計測

ちょっと書き方を変えただけで実行速度がいくらか速くなったり、遅くなったりします。cProfile で重い箇所を抽出して、time モジュール, timeit モジュールで、複数の書き方を比較検討するような流れになります。

◯ 使い方


1. 実行したい処理を文字列で書きます。

$ python -m timeit "繰り返す処理"
$ python -m timeit "4 // 3"
100000000 loops, best of 3: 0.0132 usec per loop


2. 最初に一度だけ実行したい処理は、-s オプションを使います。

$ python -m timeit -s "最初に1度だけ実行する処理" "繰り返す処理"
$ python -m timeit -s "import math" "math.floor(4 / 3)"
10000000 loops, best of 3: 0.169 usec per loop


3. 複数行にわたる場合は、次のようにスペースで区切って書きます。

$ python -m timeit "繰り返す処理の1行目" "繰り返す処理の2行目" "繰り返す処理の3行目" ...


請注意: Python;セミコロンで単文を繋げることができます。しかし ;セミコロンでは for 文のような複合文は繋げられないので注意してください。自分は、何度も弾かれました..
Why can't use semi-colon before for loop in Python?

$ python -m timeit "lst = []; for i in range(3000*3000): lst.append(None)"
...
  File "<timeit-src>", line 2
    lst = []; for i in range(3000*3000): lst.append(None)
                ^
SyntaxError: invalid syntax


4. 3. は見辛いので複数行にわたる場合は、次のようにスクリプト内で文字列にして timeit 関数に渡すような書き方もできます。

>>> import timeit
>>> s = """\
繰り返す処理の1行目
繰り返す処理の2行目
繰り返す処理の3行目
...
"""
>>>
>>> timeit.timeit(stmt=s, number=10)
11.8873
>>>

めんどくさくてパイプラインとかで渡せないかなと思って探してみたけど、パッと見なかった。スクリプト読ませたい時は -s オプションで import して、必要なところだけ実行するのが解なのかな..。あとは open 関数を使ってファイルを読ませる方法もあるかな.. あんまりそれはしたくないかな..

用語: ベンチマーク

timeit はベンチマークを取得するのに適しています。反対に cProfile はベンチマークを取得するのに適していません。

注釈: 2つのプロファイラモジュールは、与えられたプログラムの実行時プロファイルを取得するために設計されており、ベンチマークのためのものではありません (ベンチマーク用途には timeit のほうが正確な計測結果を求められます)。
27.4. Python プロファイラ


なので、timeit ではより正確な時間を計測するために、わざわざ複数回の試行を 3 回も繰り返し、もっとも早い、つまり他のプログラムの影響を受けていなかったであろう時間の平均をベンチマークの時間として提示しています。

ある特定の機能を果たすプログラムを書くときに複数の手法が存在した場合、どの手法が最も効率的かを知る上でベンチマークを取る。
プログラミング作業におけるベンチマーク | Wikipedia

◯ 実際の使い方

timeit の使い方は、次のページに掲載しました。複数の書き方のベンチマークを実際にとってみて、Python を高速化する方法を検討しています。