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
を渡すことでソート順を変更することができます。今回はデコレータ内で単純に標準出力に出力しただけですが、必要に応じて複数スレッドの結果をマージしたり、ファイルに保存するなどの対応も可能だと思います
最近のコメント