pythonで各処理の処理時間や呼び出し数の確認 (cProfile)

はじめに

データ解析をする際に，自作のコードが遅いことが多々ある．
場当たり的にtime関数を利用して時間計測をするという方法もあるが，今回はProfilingを利用したいと思う．

簡単な使い方

1. 実行時にcProfileコマンドを付与

python -m cProfile -o プロファイルを書き込みたいファイル名.prof 処理時間を計測したいファイル名.py

1. profファイル内を見るためのコードを作成

import pstats


if __name__ == "__main__":
    sts = pstats.Stats("hoge.prof")
    sts.strip_dirs().sort_stats("cumtime").print_stats(30)

1. 上記のpyファイルを実行

Mon Jun 15 02:22:15 2020    hoge.prof

         415990 function calls (415842 primitive calls) in 0.742 seconds

   Ordered by: cumulative time
   List reduced from 350 to 30 due to restriction <30>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      7/1    0.000    0.000    0.742    0.742 {built-in method builtins.exec}
        1    0.000    0.000    0.742    0.742 hoge.py:1(<module>)
        1    0.052    0.052    0.734    0.734 hoge.py:54(main)
    13338    0.337    0.000    0.337    0.000 {built-in method builtins.print}
    13337    0.013    0.000    0.284    0.000 {built-in method strptime}
    13337    0.022    0.000    0.269    0.000 _strptime.py:574(_strptime_datetime)
    13337    0.136    0.000    0.248    0.000 _strptime.py:318(_strptime)
    13339    0.008    0.000    0.056    0.000 _strptime.py:26(_getlang)
    13339    0.010    0.000    0.048    0.000 locale.py:571(getlocale)
    13339    0.007    0.000    0.027    0.000 locale.py:467(_parse_localename)
    11983    0.019    0.000    0.023    0.000 hoge.py:41(nxt_hash)
    13339    0.014    0.000    0.020    0.000 locale.py:384(normalize)
    13337    0.020    0.000    0.020    0.000 {method 'match' of 're.Pattern' objects}
    13338    0.011    0.000    0.016    0.000 hoge.py:11(read_files)
    13337    0.013    0.000    0.013    0.000 {method 'groupdict' of 're.Match' objects}
    13339    0.011    0.000    0.011    0.000 {built-in method _locale.setlocale}
     11/4    0.000    0.000    0.010    0.002 <frozen importlib._bootstrap>:978(_find_and_load)
     11/4    0.000    0.000    0.010    0.002 <frozen importlib._bootstrap>:948(_find_and_load_unlocked)
     11/4    0.000    0.000    0.009    0.002 <frozen importlib._bootstrap>:663(_load_unlocked)
      6/4    0.000    0.000    0.009    0.002 <frozen importlib._bootstrap_external>:722(exec_module)
    13337    0.009    0.000    0.009    0.000 {method 'split' of 'str' objects}
    13337    0.008    0.000    0.008    0.000 {method 'format' of 'str' objects}
    40114    0.008    0.000    0.008    0.000 {method 'get' of 'dict' objects}
     16/4    0.000    0.000    0.008    0.002 <frozen importlib._bootstrap>:211(_call_with_frames_removed)
    26674    0.004    0.000    0.004    0.000 {method 'keys' of 'dict' objects}
    26675    0.004    0.000    0.004    0.000 {method 'toordinal' of 'datetime.date' objects}
    27406    0.004    0.000    0.004    0.000 {built-in method builtins.isinstance}
27111/27083    0.004    0.000    0.004    0.000 {built-in method builtins.len}
     2947    0.003    0.000    0.003    0.000 {method 'hexdigest' of '_hashlib.HASH' objects}
    13682    0.003    0.000    0.003    0.000 {method 'rstrip' of 'str' objects}

sort_statsの引数

参考

print_statsの引数は上位K位まで列挙．

・ncalls：呼び出し回数
・tottime：注目している関数に消費された合計時間（内部で別の呼び出しをしている場合はその時間は除外）
・cumtime：tottimeの内部呼び出しも含めた計算時間