Pythonにはデコレータという機能があります。これは関数を受け取り、その関数を元にした関数を返す処理を書きやすくする機能です。これは例えば次のように使えます。
import functools
import time
# デコレータを用意。関数を受け取って関数を返せばOK
def log_function_time(func):
"""関数の実行にかかった時間と引数を表示するデコレーター"""
@functools.wraps(func)
def wrapper(*args, **kwargs):
start_time = time.time() # 開始時間
result = func(*args, **kwargs) # 関数の実行
end_time = time.time() # 終了時間
# 関数が定義されているファイル名と関数名、引数、かかった時間を表示
filename = func.__code__.co_filename
print(f"{filename}:{func.__name__!r}({args}, {kwargs}) {end_time - start_time:.4f} sec")
return result
return wrapper
# @名前とすると関数をデコレータに渡せる
@log_function_time
def wait1sec():
time.sleep(1)
if __name__ == '__main__':
wait1sec()
# log_function_timeを使っているため、以下のような出力がされます
# C:\xxx\tmp.py:'wait1sec'((), {}) 1.0117 sec
関数をラッピングする関数はどの言語でも書くことがままあります。デコレータはそういった部分を書きやすく、使いやすくしてくれます。
上記のコードはまあまあ便利なのですが非同期関数に対応していません。もしそのまま使うと次のようになります。
import asyncio
@log_function_time
async def test_async(x, y):
"""非同期関数のテスト"""
await asyncio.sleep(1) # 非同期に時間がかかる処理を模倣
return x * y
if __name__ == '__main__':
asyncio.run(test_async(2,3))
# C:\xxx\tmp.py:'test_async'((2, 3), {}) 0.0000 secs
非同期の部分を待たずに計測完了としてしまうため0秒と表示されてしまいます。適切にawaitする必要があります。つまり次のようになります。
def log_async_function_time(func):
"""非同期関数の実行にかかった時間と引数を表示するデコレーター"""
# 非同期処理に対応するために async def を使う
@functools.wraps(func)
async def wrapper(*args, **kwargs):
start_time = time.time()
result = await func(*args, **kwargs) # 非同期関数の実行を待機
end_time = time.time()
filename = func.__code__.co_filename
print(f"{filename}:{func.__name__!r}({args}, {kwargs}) {end_time - start_time:.4f} sec")
return result
return wrapper
if __name__ == '__main__':
asyncio.run(test_async(2,3))
# C:\xxx\tmp.py:'test_async'((2, 3), {}) 1.0049 sec
こちらを使うとしっかりと待機して実行時間が表示されます。
このままでも十分使えるのですが、どちらのデコレータを用いるかの使い分けが出るのは手間です。そこで引数の関数が非同期関数か否かをチェックして適切に処理するようにします。この実装が次です。
import functools
import time
import asyncio
def log_function_time(func):
"""関数の実行にかかった時間と引数をプリントするデコレータ。同期及び非同期関数に対応。"""
@functools.wraps(func)
def sync_wrapper(*args, **kwargs):
start_time = time.time()
result = func(*args, **kwargs)
end_time = time.time()
filename = func.__code__.co_filename
print(f"{filename}:{func.__name__!r}({args}, {kwargs}) took {end_time - start_time:.4f} sec")
return result
@functools.wraps(func)
async def async_wrapper(*args, **kwargs):
start_time = time.time()
result = await func(*args, **kwargs)
end_time = time.time()
filename = func.__code__.co_filename
print(f"{filename}:{func.__name__!r}({args}, {kwargs}) took {end_time - start_time:.4f} sec")
return result
# asyncio.iscoroutinefunction で非同期関数かどうかを判定
if asyncio.iscoroutinefunction(func):
return async_wrapper
else:
return sync_wrapper
@log_function_time
def test_sync():
"""同期関数のテスト"""
time.sleep(1)
@log_function_time
async def test_async():
"""非同期関数のテスト"""
await asyncio.sleep(1) # 非同期に時間がかかる処理を模倣
if __name__ == '__main__':
test_sync()
asyncio.run(test_async())
# C:\xxx\tmp.py:'test_sync'((), {}) took 1.0061 sec
# C:\xxx\tmp.py:'test_async'((), {}) took 1.0061 sec
Python組み込み関数であるasyncio.iscoroutinefunctionを用いて関数が非同期関数であるか否かをチェックし、非同期ならば非同期用処理、同期ならば同期用処理に流し込みます。こうすることでデコレータを呼び出す側は非同期関数、同期関数とそれぞれに対応するデコレータを考えずに済み、楽ができます。
先ほどのコードは使う分には便利なのですが、全く同じ意味で同じことするコードが二か所にあることとなりメンテナンスがちょっとめんどくさいです（1関数の内部なのでマシな方ではありますが）。そこで非同期、動機が絡まない部分は完全に共通化して改修しやすくしたくなります。これを実装したのが次です。
def log_function_time(func):
"""関数の実行にかかった時間と引数をプリントするデコレータ。同期及び非同期関数に対応。"""
# 関数の実行前の処理
def pre_call():
start_time = time.time()
return start_time
# 関数の実行後の処理
def post_call(start_time, *args, **kwargs):
end_time = time.time()
filename = func.__code__.co_filename
print(f"{filename}:{func.__name__!r}({args}, {kwargs}) took {end_time - start_time:.4f} sec")
@functools.wraps(func)
def sync_wrapper(*args, **kwargs):
start_time = pre_call()
result = func(*args, **kwargs)
post_call(start_time, *args, **kwargs)
return result
@functools.wraps(func)
async def async_wrapper(*args, **kwargs):
start_time = pre_call()
result = await func(*args, **kwargs)
post_call(start_time, *args, **kwargs)
return result
# asyncio.iscoroutinefunction で非同期関数かどうかを判定
if asyncio.iscoroutinefunction(func):
return async_wrapper
else:
return sync_wrapper
前後の処理をそれぞれ関数にしました。単純な方法ですがコードを改修したい時に変更する部分は大体この処理の前後の部分だけなので結構効果的です。こんな感じで同期処理非同期処理を問わず関数の実行時間を計測できます。またpre_callやpost_callの中身を書き換えることで他の何かをしたいデコレータにも同期、非同期を問わない書き方を応用できます。
