PythonでThreadのProfile
Pythonでスレッドでの実行結果をプロファイルする方法
いつも通りにcProfile (Profile)を使用した場合
以下のようなスレッドを含むコードを想定します
import threading
from threading import Thread
def my_power(v, n):
return v**n
def thread_fn1():
x = 0
for i in range(2000000):
x += my_power(i, 2)
print(f'x = {x}')
def thread_fn2():
y = 0
for i in range(1000000):
y -= my_power(i, 2)
print(f'y = {y}')
def main():
th1 = Thread(target=thread_fn1)
th2 = Thread(target=thread_fn2)
th1.start()
th2.start()
th1.join()
th2.join()
return 0
if __name__ == "__main__":
main()
上記コードをcProfileで普通にプロファイルすると、以下のように{method 'acquire' of '_thread.lock' objects}が処理の大半を占めているという結果が出力されます。これは-m cProfileでプロファイルされる対象がMain Threadのみになるためです。
% python -m cProfile -s cumtime thread_profile.py
y = -333332833333500000
x = 2666664666667000000
867 function calls (865 primitive calls) in 2.411 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
3/1 0.000 0.000 2.411 2.411 {built-in method builtins.exec}
1 0.000 0.000 2.411 2.411 thread_profile.py:1(<module>)
1 0.000 0.000 2.405 2.405 thread_profile.py:49(main)
12 2.404 0.200 2.404 0.200 {method 'acquire' of '_thread.lock' objects}
2 0.000 0.000 2.388 1.194 threading.py:979(join)
2 0.000 0.000 2.388 1.194 threading.py:1017(_wait_for_tstate_lock)
2 0.000 0.000 0.017 0.008 threading.py:834(start)
2 0.000 0.000 0.017 0.008 threading.py:540(wait)
2 0.000 0.000 0.017 0.008 threading.py:270(wait)
2 0.000 0.000 0.006 0.003 <frozen importlib._bootstrap>:986(_find_and_load)
2 0.000 0.000 0.006 0.003 <frozen importlib._bootstrap>:956(_find_and_load_unlocked)
2 0.000 0.000 0.004 0.002 <frozen importlib._bootstrap>:650(_load_unlocked)
2 0.000 0.000 0.004 0.002 <frozen importlib._bootstrap_external>:777(exec_module)
2 0.000 0.000 0.003 0.002 <frozen importlib._bootstrap_external>:849(get_code)
4 0.000 0.000 0.002 0.000 <frozen importlib._bootstrap_external>:969(get_data)
2 0.000 0.000 0.002 0.001 <frozen importlib._bootstrap>:890(_find_spec)
2 0.000 0.000 0.002 0.001 <frozen importlib._bootstrap_external>:1334(find_spec)
2 0.000 0.000 0.002 0.001 <frozen importlib._bootstrap_external>:1302(_get_spec)
6 0.000 0.000 0.001 0.000 <frozen importlib._bootstrap_external>:1431(find_spec)
4 0.001 0.000 0.001 0.000 {built-in method io.open_code}
Threadのプロファイル
そこで、スレッドでの実行結果をプロファイルするために、スレッド上でcProfileを実行する必要があります。cProfileを実行するために、下記のようにラッパー関数: thread_prof_wrapを準備して実行してみます
import cProfile
def thread_prof_wrap(f, *args, **kwargs):
pr = cProfile.Profile()
pr.runcall(f, *args, **kwargs)
pr.print_stats()
th = Thread(target=thread_prof_wrap, args=(thread_fn1,))
th.start()
th.join()
上記を実行するとスレッド上でのプロファイルが計測され、しっかりmy_power()の処理時間が表示されます
% python thread_profile.py
x = 2666664666667000000
2000007 function calls in 1.226 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
2 0.000 0.000 0.000 0.000 cp1252.py:18(encode)
2000000 0.710 0.000 0.710 0.000 thread_profile.py:23(my_power)
1 0.516 0.516 1.226 1.226 thread_profile.py:28(thread_fn1)
2 0.000 0.000 0.000 0.000 {built-in method _codecs.charmap_encode}
1 0.000 0.000 0.000 0.000 {built-in method builtins.print}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
デコレータで整形
上記のままでもいいですが、thread_prof_wrapはラッパー関数のためデコレータを使用して下記のように実装してみました
import cProfile
from pstats import SortKey
import threading
from threading import Thread
from functools import wraps
def thread_profile(sort_key):
def inner(f):
@wraps(f)
def wrapper(*args, **kwargs):
th = threading.current_thread()
pr = cProfile.Profile()
pr.runcall(f, *args, **kwargs)
print(f'[{th.name}] end of thread')
stats_file = f'{th.name}.prof'
print(f'[{th.name}] dumping prof to {stats_file}')
pr.print_stats(sort_key)
return wrapper
return inner
def my_power(v, n):
return v**n
@thread_profile(sort_key=SortKey.CUMULATIVE)
def thread_fn1():
x = 0
for i in range(2000000):
x += my_power(i, 2)
print(f'x = {x}')
@thread_profile(sort_key=SortKey.TIME)
def thread_fn2():
y = 0
for i in range(1000000):
y -= my_power(i, 2)
print(f'y = {y}')
def main():
th1 = Thread(target=thread_fn1)
th2 = Thread(target=thread_fn2)
th1.start()
th2.start()
th1.join()
th2.join()
return 0
if __name__ == "__main__":
main()
デコレータを追加、削除するだけでプロファイルの有無を変更できます。またデコレータにSortKeyを渡すことでソート順を変更することができます。今回はデコレータ内で単純に標準出力に出力しただけですが、必要に応じて複数スレッドの結果をマージしたり、ファイルに保存するなどの対応も可能だと思います
最近のコメント