Python cProfile でコードのパフォーマンスを解析する

April 16, 2023

Python の cProfile は、Python プログラムの実行中にコードのプロファイリングを行うためのモジュールです。プロファイリングとは、コードのパフォーマンスを評価し、特に実行時間や呼び出し回数などの情報を収集して解析することです。cProfile は、関数ごとに実行時間、呼び出し回数、1回あたりの平均時間などのデータを提供します。

本記事では、cProfile によるプロファイリングの実行方法を解説します。

なお、利用するサンプルコードは、以下のページに公開しています。

https://github.com/hnishi/hello-cprofile/tree/main

プロファイリング実行方法

cProfile は Python の標準ライブラリに含まれており、次のように使用することができます。

python -m cProfile -o profile_hello.pstats hello.py

ここで、hello.py は解析対象のコードです。プロファイリング結果を profile_hello.pstats ファイルに保存します。

python: Pythonインタープリタを実行するコマンド。
-m cProfile: Pythonインタープリタに、cProfileモジュールをモジュールとして実行するよう指示します。
-o profile_hello.pstats: -oオプションは、プロファイリング結果を指定されたファイル名（ここではprofile_hello.pstats）に保存することを指示します。ファイルはバイナリ形式のpstatsファイルとして保存されます。
hello.py: プロファイリングを実行する対象のPythonスクリプトです。

このコマンドを実行すると、hello.pyスクリプトがプロファイリングされ、その結果がprofile_hello.pstatsファイルに保存されます。保存されたpstatsファイルは、後で解析や可視化のために読み込むことができます。例えば、Pythonの標準ライブラリに含まれるpstatsモジュールや、gprof2dot、pyprof2calltreeなどのサードパーティツールを使用してプロファイリングデータを解析できます。

解析結果の確認

以下のようなスクリプト (analyze.py) を用意します。

import sys
import pstats
from pstats import SortKey


def main():
    print(sys.argv)
    p = pstats.Stats(sys.argv[1])
    p.sort_stats(SortKey.TIME).print_stats(10)
    p.print_callers()
    # p.print_callees()


if __name__ == '__main__':
    main()

以下のように実行して、解析結果を確認します。

python analyze.py profile_hello.pstats

出力結果は、下記のようになります。

$ python analyze.py profile_hello.pstats
['analyze.py', 'profile_hello.pstats']
Tue Dec 15 10:50:35 2020    profile_hello.pstats

         49 function calls in 3.561 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       15    3.560    0.237    3.560    0.237 {built-in method time.sleep}
       15    0.001    0.000    0.001    0.000 {built-in method builtins.print}
        1    0.000    0.000    3.561    3.561 hello.py:12(main)
       10    0.000    0.000    1.043    0.104 hello.py:4(sleep_100ms)
        5    0.000    0.000    2.517    0.503 hello.py:8(sleep_500ms)
        1    0.000    0.000    3.561    3.561 {built-in method builtins.exec}
        1    0.000    0.000    3.561    3.561 hello.py:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}


   Ordered by: internal time

Function                                          was called by...
                                                      ncalls  tottime  cumtime
{built-in method time.sleep}                      <-      10    1.043    1.043  hello.py:4(sleep_100ms)
                                                           5    2.517    2.517  hello.py:8(sleep_500ms)
{built-in method builtins.print}                  <-      15    0.001    0.001  hello.py:12(main)
hello.py:12(main)                                 <-       1    0.000    3.561  hello.py:1(<module>)
hello.py:4(sleep_100ms)                           <-      10    0.000    1.043  hello.py:12(main)
hello.py:8(sleep_500ms)                           <-       5    0.000    2.517  hello.py:12(main)
{built-in method builtins.exec}                   <-
hello.py:1(<module>)                              <-       1    0.000    3.561  {built-in method builtins.exec}
{method 'disable' of '_lsprof.Profiler' objects}  <-

この解析結果は、profile_hello.pstatsファイルに保存されたプロファイリングデータを解析したものです。結果は、関数ごとに実行時間、呼び出し回数などの情報が表示されています。

解析結果の主要な部分を説明します：

まず、49 function calls in 3.561 secondsと表示されており、合計49回の関数呼び出しが行われ、全体の実行時間が3.561秒であることを示しています。
次に、「Ordered by: internal time」という部分があります。これは、リストされた関数が実行時間（内部時間）順にソートされていることを示しています。各関数について、以下の情報が提供されています。
- ncalls：関数が呼び出された回数。
- tottime：関数の純粋な実行時間（他の関数の呼び出しにかかった時間を除く）。
- percall：関数の平均実行時間（tottime / ncalls）。
- cumtime：関数の累積実行時間（関数自体とそのすべての子関数の実行時間を含む）。
- filename:lineno(function)：関数の定義があるファイル名、行番号、および関数名。
最後に、「Ordered by: internal time」と表示される部分がありますが、これは同じ情報が関数の呼び出し元に基づいて表示されていることを示しています。つまり、どの関数がどの関数によって呼び出されたかが表示されています。また、呼び出し元ごとに、呼び出し回数（ncalls）、実行時間（tottime）、累積実行時間（cumtime）が表示されています。

この解析結果を見ることで、コードのどの部分がパフォーマンスに影響を与えているかを把握し、最適化が必要な箇所を特定できます。この例では、time.sleep関数が最も実行時間が長く、hello.py内のsleep_100msとsleep_500ms関数から呼び出されていることが分かります。

可視化

解析結果を図にすることで、どこがパフォーマンスのボトルネックになっているか、わかりやすくなります。

ここでは、gprof2dot と graphviz を利用した例を示します。

Mac OS にインストールする例は下記です。

brew install graphviz
pip install gprof2dot

図を作成するには、下記のように実行します。

gprof2dot -f pstats profile_hello.pstats | dot -Tpng -o profile_hello.png

このコマンドは、profile_hello.pstatsファイルに保存されたプロファイリングデータを可視化し、profile_hello.pngという名前の画像ファイルに保存します。このコマンドは、gprof2dotとGraphvizのdotツールを使用しています。

コマンドの各部分の説明：

gprof2dot: サードパーティのプロファイリングデータ可視化ツール。プロファイリングデータをGraphvizのdot形式に変換します。
-f pstats: 入力ファイル形式を指定します。ここでは、pstats形式（PythonのcProfileモジュールが生成する形式）を指定しています。
profile_hello.pstats: 入力として使用されるプロファイリングデータファイルです。
|: パイプ。前のコマンドの出力を次のコマンドの入力として渡します。
dot: Graphvizのコマンドラインツールで、dot形式のグラフを様々な形式に変換します。
-Tpng: 出力ファイル形式を指定します。ここでは、PNG形式を指定しています。
-o profile_hello.png: 出力ファイル名を指定します。ここでは、profile_hello.pngを指定しています。

このコマンドを実行すると、gprof2dotがprofile_hello.pstatsファイルを読み込み、dot形式に変換します。次に、dotツールがそのdot形式のデータを読み込み、PNG画像としてprofile_hello.pngに保存します。この画像ファイルには、プロファイリングデータがグラフとして可視化されており、関数呼び出しの階層や実行時間がわかりやすく表示されています。これにより、コードのパフォーマンス問題を特定しやすくなります。

出力結果の図は下記のようになります。

処理に時間がかかっている箇所が赤色で図示されており、呼び出しの順序もわかりやすいですね。

まとめ

解説は以上となります。

手元で試されたい場合は、以下のページのコードを参考にしてください。

https://github.com/hnishi/hello-cprofile/tree/main

.css-yixlj4{margin-left:-20px;padding-right:4px;color:var(--theme-ui-colors-primary);}プロファイリング実行方法

解析結果の確認

可視化

まとめ

プロファイリング実行方法