Python 実行時間計測メモ

いきなりの結論

結局は、perf_counter() が無難。
目新しいことはないので読む価値はないかもしれません。

想定読者

Pythonで実行速度を計測したがあるけれども、深くは考察していなかった方あたりでしょうか。

調べたきっかけ

実行時間を計測するためにうっかりtime.time()を使っていました。
精度等を気にする必要がないので十分だったのですが、独立しているはずの関数の実行順を変更したら実行時間が大きく変わりました。
それの原因は不明ですが、これをきっかけに時間計測に関して調べ直すことにしました。
(関数自体が実用に耐えないものだった原因究明はあきらめました。ガベージコレクションが影響しているのかも)

環境

Windows 10 Pro 64bit
Python 3.8.3

timeモジュール

標準ライブラリであるtimeモジュールのみ考えます

2点間の実行時間を計測するための関数

実行時間を計測するためにtimeモジュールで使える関数は以下になります。
time.get_clock_info()で調べた場合に、monotonic=Trueであるものです。
つまり、外部要因などで減算されないことが保証されているものです。

name	purpose	description	sleep	resolution
perf_counter()	実時間の計測	パフォーマンスカウンターの値	含める	高い
process_time()	プロセスにおいて実際に稼働した時間の計測	現在のプロセスのシステムおよびユーザーの CPU 時間の合計値	含めない	高い(低い)
thread_time()	スレッドにおいて実際に稼働した時間の計測	現在のスレッドのシステムおよびユーザーの CPU 時間の合計値	含めない	高い(低い)
monotonic()	システム時刻の経過時間の計測	システムを起動した後の経過時間	含める	低い

分解能が"高い(低い)"とは何を書いているのだと思いますが、time.get_clock_info()で得られる仕様が高分解能となっているのに、実際に動かしてみると低分解能なのでこのように表記しています。
自分の開発環境の影響があるのかもしれません。

少し解説すると、以下のようになります。

perf_counter()は、プログラムが動いてから現実時間がどの程度経過したかを計測するのに使います。
スリープ時の経過時間も含めますので意図した時間が出ない可能性もあります。
ただし、一番安定しているようです。
timeitなどでデフォルトのtimerに設定されているなど、これを使うのが無難なようです。

process_time()またはthread_time()は、プロセス(スレッド)においてプログラムが確実に動いた時間を調べるのに使います。
自分を含めて多くの方がこの時間を計測したいのだと思います。
しかし、実際の分解能が仕様と違って低いようです。
本当はこれを使いたいのですが、使用をためらってしまいます。
また、Windowsの場合、実際はCのGetProcessTimes()を使っているのですが、それの説明には、

text

Note that this value can exceed the amount of real time elapsed (between lpCreationTime and lpExitTime) if the process executes across multiple CPU cores.

と書いてあります。
あまり信頼できるものではないようです。

monotonic()は、システムの稼働時間を調べるのに使います。
つまり、このPCは稼働してから何日経ったかとかを調べるのに使います。
あまり使う事はないと思います。

time()は、時刻を得るものであって実行時間計測には使わない。

ガーベジコレクションの影響

ガーベジコレクションは、プログラムの実行速度に影響を及ぼすようです。
下記で説明するtimeit()は、その影響を避けるためにデフォルトの動作としてガーベジコレクションを停止しています。
同じようにガーベジコレクションの影響を計測から除外したいのならばガーベジコレクションを停止する必要があります。
その方法は、以下のように記述することです。
追記
停止前にガーベジコレクションを実行したほうが安定するようです。

python

import gc

gc.collect() # ガーベジコレクションの実行
gc.disable() # 停止
# 計測処理
gc.enable() # 再開

使い方

timeモジュールの使い方と言っても単純ですが、下記のように計測したい前後で時間を取りそれを減算すれば良いだけです。

python

import time
import timeit

def stopwatchPrint(func):

  @functools.wraps(func)
  def wrapper(*args, **kwargs):
    start = time.perf_counter()
    result = func(*args, **kwargs)
    end = time.perf_counter()
    print(f"{func.__name__}: {end - start:.3f} s.")
    return result

  return wrapper

@stopwatchPrint
def func1():
  # 何かの処理
  return

def func2():
  start = time.perf_counter()
  # 何かの処理
  end = time.perf_counter()
  print(f"実行時間: {end - start}"
  return

timeitモジュール

基本的には、上記のようにtimeを使えば良い問題ありません。
しかし、標準ライブラリには、実行速度を計測するためにtimeitも用意されています。
ほとんどtime.perf_counter()を呼んでいるだけですが、軽く解説してみます。
コマンドラインからの使い方は、触れません。
2つの関数を上げていますが、timeit.repeat()だけを使えば良いと思います。

python

import time
import timeit

timeit.timeit(stmt=func1, setup=func2, timer=time.time.perf_counter, number=1000000)
timeit.repeat(stmt=func1, setup=func2, timer=time.time.perf_counter, number=1000000, repeat=5)

• timeit():
  • stmt: 実行時間を計測したい関数、もしくは式として評価できる文字列を渡す。文字列の場合は、eval()で評価される。
  • setup: 前処理を行う関数、もしくは式として評価できる文字列を渡す。これの実行時間は、計測値には含まれない。
  • timer: 計測に使うtimer関数を渡す。デフォルトは、time.time.perf_counter。time.process_time等を渡しても良い。
  • number: 実行回数。デフォルトは、1000000。
  • globals: 名前空間を指定する。デフォルトは、None。変更したい場合は、globals=globals()やglobals=locals()など指定する。
• repeat(): timeitの繰り返し版。timeitの引数に加えて以下を持つ。
  • repeat: 繰り返し回数。 number=100, repeat=3ならば100回の実行を3回繰り返す。

使い方

実際には、以下のように使います。
resultは、1つの要素がlongLongLongCat()を100回の実行したときの経過時間で長さが3のリストです。

python

def longLongLongCat(): # 時間を計測したい関数
   pass

result = timeit.repeat(longLongLongCat, ,number=100, repeat=3)
print(result)

ガーベジコレクションの影響を排除したいならば、以下の様にsetup=gc.collectを渡した方が良いかもしれない。

python

result = timeit.repeat(longLongLongCat, setup=gc.collect, number=100, repeat=3)
print(result)

timeitの実行関数に引数を渡す

timeitの実行関数は、引数を渡すようになっていません。
文字列で実行する前提なのかもしれませんが、それを標準的に使うには抵抗があります。
そのため、色々と試してみました。
他に旨い方法があるのかもしれませんが、lambdaで渡すのが一番楽なようです。

python

a = 10
b = 12
timeit.repeat(lambda: print(a, b), number=1000, repeat=5)

python

import math
import timeit
import functools

def func():
  print("func")

def funcN(n):
  print(f"funcN: {n}")

class Test():
  def __init__(self, n=100, r=3):
    self.number = n
    self.repeat = r

  def glo(self):
    #print(globals())
    #print(locals())
    result = timeit.repeat("print(a, b)", number=self.number, repeat=self.repeat, globals=globals())
    print(result)

  def loc(self):
    a = 33
    b = 4
    #print(globals())
    #print(locals())
    result = timeit.repeat("print(a, b)", number=self.number, repeat=self.repeat, globals=locals())
    print(result)

  def mix(self):
    a = 33
    b = 44
    #print(globals())
    #print(locals())
    result = timeit.repeat("print(a , b)", number=self.number, repeat=self.repeat, globals={"a": 30, "b": 50})
    print(result)
    result = timeit.repeat("print(a , b)", number=self.number, repeat=self.repeat, globals={
        "a": globals()["a"],
        "b": locals()["b"]
    })
    print(result)

a = 2525
b = 2828
t = Test(1, 1)
t.glo()
t.loc()
t.mix()

timeit.repeat(func, number=1, repeat=1)
timeit.repeat(lambda: print(a, b), number=1, repeat=1)
n = 1129
timeit.repeat("funcN(n)", number=1, repeat=1, globals=globals())
timeit.repeat("funcN(n)", number=1, repeat=1, globals={"funcN": funcN, "n": 714})
g = globals()
g.update({"n": 1374})
timeit.repeat("funcN(n)", number=1, repeat=1, globals=g)
timeit.repeat(functools.partial(funcN, 184), number=1, repeat=1)

出力結果

shell

2525 2828
[0.001136100000000001]
33 4
[0.026095200000000013]
30 50
[0.01867479999999999]
2525 44
[0.001263299999999995]
func
2525 2828
funcN: 1129
funcN: 714
funcN: 1374
funcN: 184

クロックの情報

自分の環境での情報です。

shell

>>> time.get_clock_info("monotonic")
namespace(adjustable=False, implementation='GetTickCount64()', monotonic=True, resolution=0.015625)

>>> time.get_clock_info("perf_counter")
namespace(adjustable=False, implementation='QueryPerformanceCounter()', monotonic=True, resolution=1e-07)

>>> time.get_clock_info("process_time")
namespace(adjustable=False, implementation='GetProcessTimes()', monotonic=True, resolution=1e-07)

>>> time.get_clock_info("thread_time")
namespace(adjustable=False, implementation='GetThreadTimes()', monotonic=True, resolution=1e-07)

>>> time.get_clock_info("time")
namespace(adjustable=True, implementation='GetSystemTimeAsFileTime()', monotonic=False, resolution=0.015625)

---

timeitモジュールを使った自作の測定関数とデコレータ

毎回timeitを使った処理を書くのも面倒なので、もう少し使いやすい形の関数を定義してみました。
計測したい関数にprint()が使われていると支障があるのでそれの無効化も併せて行います。
そのため、print()の実行時間も含めたいときには使用できません。

コード

定義

import timeit
import time
import gc
import statistics
import functools
import contextlib


def printStatistics(lt, fmt="e"):
  print(f"{lt}")
  print(f"合計(sum)                    : {sum(lt):{fmt}}")
  print(f"平均(mean)                   : {statistics.mean(lt):{fmt}}")
  print(f"中央値(median)               : {statistics.median(lt):{fmt}}")
  print(f"最頻値(mode)                 : {statistics.mode(lt):{fmt}}")
  print(f"標準偏差(standard deviation) : {statistics.pstdev(lt):{fmt}}")
  print(f"分散(variance)               : {statistics.pvariance(lt):{fmt}}")


def measure(func, *args, setup=gc.collect, timer=time.perf_counter, repeat=5, number=1000000, globals=None, fmt="e", **kwargs):
  print(func.__name__, args, kwargs)
  print(f"{number} * {repeat}: {timer.__name__}")
  with contextlib.redirect_stdout(None):
    result = timeit.repeat(lambda: func(*args, **kwargs), setup=setup, timer=timer, repeat=repeat, number=number, globals=globals)
  printStatistics(result, fmt)


def measureDecorator(setup=gc.collect, timer=time.perf_counter, repeat=5, number=1000000, globals=None, fmt="e"):

  def meseureWrapper(func):

    @functools.wraps(func)
    def wrapper(*args, **kwargs):
      result = func(*args, **kwargs)
      measure(func, *args, setup=setup, timer=timer, repeat=repeat, number=number, globals=globals, fmt=fmt, **kwargs)
      return result

    return wrapper

  return meseureWrapper

解説

measure() は、関数版で時間を計測したい関数とそれに渡す引数を渡して実行します。
測定対象の関数とtimeit.repeat()のキーワード引数の名前が同じ場合は、想定通りの動作にならないので注意してください。
計測中のprint()は、contextlib.redirect_stdout(None)で無効化しています。

@measureDecorator() は、デコレータ版です。
デコレータとして使う事は無いかもしれないが作ってみました。

使い方

def t1(*args, **kwargs):
  print(args, kwargs)


@measureDecorator(repeat=3, number=100)
def t2(*args, **kwargs):
  print(args, kwargs)


measure(t1, 1, 2, 3, k=5, l=6, repeat=3, number=100)
t2(1, 2, 3, k=5, l=6)

実行結果例

t1 (1, 2, 3) {'k': 5, 'l': 6}
100 * 3: perf_counter
[3.42000275850296e-05, 3.1800009310245514e-05, 3.160000778734684e-05]
合計(sum)                    : 9.760004e-05
平均(mean)                   : 3.253335e-05
中央値(median)               : 3.180001e-05
最頻値(mode)                 : 3.420003e-05
標準偏差(standard deviation) : 1.181345e-06
分散(variance)               : 1.395577e-12
(1, 2, 3) {'k': 5, 'l': 6}
t2 (1, 2, 3) {'k': 5, 'l': 6}
100 * 3: perf_counter
[3.360002301633358e-05, 3.1400006264448166e-05, 3.15000070258975e-05]
合計(sum)                    : 9.650004e-05
平均(mean)                   : 3.216668e-05
中央値(median)               : 3.150001e-05
最頻値(mode)                 : 3.360002e-05
標準偏差(standard deviation) : 1.014349e-06
分散(variance)               : 1.028905e-12