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