Python｜出力内容を調整可能なプロファイリング用デコレータ

Pythonでプロファイリングする場合、標準ライブラリのcProfileを使うことが多いのではないでしょうか。

この記事では、そのcProfileを使ったプロファイリング時に活用できる、既存の処理を邪魔せず、使いまわしやすいデコレータについて説明します。

さらに、大きな処理をプロファイリングしようとすると、出力が多すぎて見づらくなってしまうことがありますが、紹介するデコレータは出力内容を調整可能です。

プロファイリング用デコレータのコード
使用方法
参考

プロファイリング用デコレータのコード

cProfileを使ったプロファイリング用デコレータのコードは下の通りです。一度実装しておけば、プロファイリングしたい関数にデコレータを付けるだけで、プロファイルの統計情報が取得できるようになります。

profile_util.py

import cProfile
import pstats
from functools import wraps

def profile(
    sort_key=pstats.SortKey.CUMULATIVE,   # 累積時間が多い順に出力する
    file_name_regex=None,   # file_nameの条件なし
    output_line=10  # 10件分出力する
):
    """
    関数プロファイリング用デコレータ。
    """

    def _profile(func):
        @wraps(func)
        def _wrapper(*args, **kwargs):
            # プロファイルデータを収集
            with cProfile.Profile() as pr:
                ret = func(*args, **kwargs)

            # Statsクラスに変換して、プロファイルデータを解析
            p = pstats.Stats(pr)
            p = p.sort_stats(sort_key)

            # file_name_regex, output_lineを条件として抽出した結果を出力
            p.print_stats(file_name_regex, output_line)

            return ret

        return _wrapper

    return _profile

使用方法

下の関数をプロファイリング対象とする場合を例として、使用方法を説明します。

test_profile.py

import re

def test_profile(string):
    """ プロファイリング対象の関数 """
    re.compile(string)

    return "done"

if __name__ == "__main__":
    ret = test_profile("foo|bar")

    print(f"return: {ret}")

デフォルトの使い方

デコレータがあるモジュールをインポートし、プロファイリングしたい関数の上に@profile()を付けるだけです。

test_profile.py

import re
from profile_util import profile  # 追加


@profile()  # 追加
def test_profile(string):
    """ プロファイリング対象の関数 """
    re.compile(string)

    return "done"

if __name__ == "__main__":
    ret = test_profile("foo|bar")

    print(f"return: {ret}")

実行結果は下の様なフォーマットで標準出力されます。デフォルトでは、累積時間が多い順に10件分出力します。

         218 function calls (211 primitive calls) in 0.000 seconds

   Ordered by: cumulative time
   List reduced from 43 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 /home/user1/python/test_profile.py:5(test_profile)
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/__init__.py:225(compile)
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/__init__.py:272(_compile)
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/_compiler.py:738(compile)
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/_parser.py:970(parse)
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/_compiler.py:571(_code)
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/_parser.py:447(_parse_sub)
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/_compiler.py:509(_compile_info)
        2    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/_parser.py:507(_parse)
      3/1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/_compiler.py:37(_compile)


return: done

return: doneが出力されていることから、test_profile関数に引数、返値があっても問題なく動作することが分かります。

プロファイリングが完了したら、そのままだと処理が遅くなりますので、デコレータを削除、もしくはコメントアウトしてください。

出力件数を調整したい場合の使い方

@profile()の引数output_lineに出力したい件数を設定してください。5件出力したい場合は@profile(output_line=5)となり、出力結果はこのようになります。

         218 function calls (211 primitive calls) in 0.000 seconds

   Ordered by: cumulative time
   List reduced from 43 to 5 due to restriction <5>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 /home/user1/python/test_profile.py:5(test_profile)
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/__init__.py:225(compile)
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/__init__.py:272(_compile)
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/_compiler.py:738(compile)
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/_parser.py:970(parse)


return: done

出力したいfilenameに条件を付ける場合の使い方

@profile()の引数file_name_regexに条件を正規表現で指定してください。filenameにはパッケージ名やモジュール名、関数名が含まれるため、条件指定したこれらのみを出力させることができます。__init__.pyモジュール、またはcompile関数を出力したい場合は@profile(file_name_regex="__init__.py|\(compile\)")となり、出力結果はこのようになります。

         218 function calls (211 primitive calls) in 0.000 seconds

   Ordered by: cumulative time
   List reduced from 43 to 3 due to restriction <'__init__.py|\\(compile\\)'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/__init__.py:225(compile)
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/__init__.py:272(_compile)
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.11/re/_compiler.py:738(compile)


return: done

出力順を変える場合の使い方

@profile()の引数sort_keyに、pstats.SortKeyの変数、もしくは該当する文字列を設定してください。詳細はこちらを参照ください。

参考

この記事は以下の情報を参考にしました。