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

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

◯ デコレータを使って

デコレータは関数の前後に処理を追加する時に使います。これを応用して実行時間を計測します。
Python の デコレータとクロージャ

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

import time


def measure(func):
    def wrapper(*args, **kargs):
        start_time = time.time()
        
        result = func(*args, **kargs)
        
        execution_time = time.time() - start_time
        print(f'{func.__name__}: {execution_time}')
        return result
    return wrapper


@measure
def factorize(n):
    b = 2
    fct = []
    while b * b <= n:
        while n % b == 0:
            n //= b
            fct.append(b)
        b = b + 1
    if n > 1:
        fct.append(n)
    return fct


factorize(6700417 * 2147483647)


# 再帰呼び出しには使えないので
# @measure
def fib(n):
    if n in (0, 1):
        return 1
    else: 
        return fib(n - 2) + fib(n - 1)


# こんな感じで呼び出します。
measure(fib)(30)


どの関数がどれくらい処理時間を調べることを、プロファイルを取ると言ったりします。昔、プロファイルを取るのに、これを使おうとしてハマりました。プロファイルをとったりするのではなく、単純に実行時間を計測したりする場合は、とてもいい方法だと思います。

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

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

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)
...


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

そうやって cProfile で全体から重い箇所を抽出して、特定した思い箇所は time コマンド, time モジュールを使って複数の書き方を比較検討するような流れになるかなと思います。


抑えておきたいポイントは、次の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 モジュール, cProfile モジュールに比べて、より正確な値を計測できます。
27.5. timeit — 小さなコード断片の実行時間計測

◯ 使い方


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

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

100000000 回の loop を 3 回行って、その中で最も速かった平均値は 0.0132 usec

「最も速かった平均値」を結果として、提示しているのは恐らく「最も影響を受けていなかった時の時間」という意味合いかなと思っています。100000000 は -n オプションで, 3 は -r オプションで、指定できます。



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行目" ...
$ # list と tuple の生成
$ python -m timeit "[1,2,3]" "[1,2,3]" "[1,2,3]"
10000000 loops, best of 3: 0.18 usec per loop
$ python -m timeit "(1,2,3)" "(1,2,3)" "(1,2,3)"
10000000 loops, best of 3: 0.0221 usec per loop


;セミコロンで 単純文 を繋げることができます。

$ python -m timeit "(1,2,3);(1,2,3);(1,2,3)"
10000000 loops, best of 3: 0.0221 usec per loop
$ python -m timeit "[1,2,3];[1,2,3];[1,2,3]"
10000000 loops, best of 3: 0.181 usec per loop


ただし ;セミコロンでは for 文のような 複合文 は繋げられません。
自分は、何度も弾かれました...

$ 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

Why can't use semi-colon before for loop in Python?



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

>>> import timeit
>>> stmt = """\
繰り返す処理の1行目
繰り返す処理の2行目
繰り返す処理の3行目
...
"""
>>> # 1,000,000 回実行した総実行時間
>>> timeit.timeit(stmt)
11.8873
>>>


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

疑問: timeit モジュールはどういうときに使うの?

time コマンド, time モジュールの結果のばらつきが気になるようになったら、timeit モジュールの使いどきだと思います。

気にならなければ、ここに来たワイのようなあまり慣れていない人は、time コマンド, time モジュールでいいかなとも思います。timeit モジュールは、面倒です。コードを都度、文字列にしないといけないので。

例えば、下記のリンク先の記事では、質問者さんが、そのばらつきを気にしていて、 回答者から timeit を使いなよー。と指摘されています。
Why is there no xrange function in Python3?
xrange | Python 2.7.x と 3.x の決定的な違いを例とともに

用語: ベンチマーク

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

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


なので、timeit ではより正確な時間を計測するために、わざわざ複数回の試行を 3 回も繰り返し、その3回の中でもっとも速かった時間を、他のプログラムの影響を受けていなかった正確な時間であるとして、提示しています。

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

◯ 実際の使い方

timeit はペンチマークのために使います。実際に複数の書き方を timeit を使って比較する書くときは function_list と argument_list を用意して for 文で回すとやりやすいかなと思います。timeit を使って素因数分解を比較したコードを例として記します。
4_3_prime_decomposition.py

次のページでは、 timeit を使って複数の書き方のベンチマークを実際にとってみて、どのような書き方なら速いのかついて検討しています。