Python アプリケーションのパフォーマンス調査に便利な Cloud Profiler の結果を見るコツ

この記事はGO Inc. Advent Calendar 2024 14日目の記事です。

こんにちは。AI技術開発部の牧瀬です。

Python アプリケーションのパフォーマンスチューニングに使えるプロファイラはいくつかありますが、本番環境でも使えるものとして Google Cloud Profiler があります。本記事では様々なサンプルコードで Cloud Profiler の挙動を確認し、結果の読み方について注意点やコツをお伝えします。

概要

Google Cloud では Cloud Profiler というものが提供されており、 Go, Python, Java, Node.js などのプログラムのプロファイリングを簡単に行うことができます。対象のプログラムは Google Cloud 上で動作しているものに限らず、他のクラウド上で動作しているプログラムや、ローカルマシン上で実行するプログラムもプロファイリングできます。

Cloud Profiler の特徴:

サンプリングプロファイラであるため負荷が小さい。本番環境で常に有効化して継続的にプロファイリングすることもできる
少量のコードを記述するだけで導入でき、プロファイル結果をクラウドに送ってくれるので、ビルドプロセスの変更や出力ファイルの取り回しなどが不要で、簡単に利用できる

Cloud Profiler は対象のプログラミング言語により、取得できる情報に違いがあり、Python 版では CPU time(CPU時間) と Wall time(経過時間) のみになります。

この Python 版のプロファイラなのですが、Python には様々な言語機能があることも相まって、何が計測できて、何が計測できないのか、やや掴みづらい所があります。そこで今回は、単純なコードを書いてみて、それがプロファイル結果にどう現れるのかを見てみたいと思います。

この記事の目的は、Cloud Profiler の Python 版を利用する際、思うような出力が得られなかった場合に、それがプロファイラの仕様なのか、単にその部分に実行時間がかかっていないだけなのか、といったことを区別するためのヒントを提供したいというものです。

なお、今回、そもそもプロファイリングとは何なのかや、Cloud Profiler の導入方法については触れませんので、適宜上記リンクなどを参照ください。

サンプリングプロファイラの仕組み

先にサンプリングプロファイラの仕組みについて触れておきます。

Cloud Profiler では、プロファイラをスタートすると、1分間のうち 10秒間動作して、プロファイル情報を取得します。ランダム化されているため正確に 1分毎ではないですが、平均すると 1分間のうち 10秒間動作する、という形です。

この 10秒間の計測が「1プロファイル」になります。複数のプロファイルがある場合には、Cloud Profiler コンソール画面上では平均された結果が表示されます。

この 10秒間の計測時間の間、定期的(10ms など)に「今どこを実行しているか」を記録しておき、それを集計して表示するのが CPU time プロファイルや Wall time プロファイルになります。何度も同じ関数を通っていれば、それだけその関数のトータルの実行時間が長いということになります。

これがサンプリングプロファイラの特徴的な所で、仮に全ての関数に実行時間を計測するようなコードを入れれば、正確な結果が得られますが、オーバーヘッドが大きくなります。サンプリングプロファイラは、時々動いてプログラムの動作状況を取得することで、低負荷でプログラムの統計的な性質を明らかにすることに主眼を置いています。

Wall time プロファイルの場合、10ms 毎に Python のフレーム情報を取得し、今どの関数を実行しているかを記録することで、その関数の実行にかかった時間を計測します。

CPU time プロファイルも似た仕組みなのですが、setitimer() の ITIMER_PROF オプションを使い、 CPU 時間を 10ms 使う毎に Python のフレーム情報を取得し、今どの関数を実行しているかを記録することで、その関数の実行に費やした CPU 時間を計測します。

このような Cloud Profiler の詳細動作については、プロファイラエージェントのソースコード(Python版)が参考になります。

Cloud Profiler を実際に動かしてみる

では実際に Python コードを書いて、どのようなプロファイル結果になるかを見てみましょう。Python のバージョンは 3.11 です。

今回作成したソースコード一式はこちらにあります。

python で CPU を使う処理

以下のようなコードのプロファイルを取得します。python で適当なループ処理をして、CPU を使います。

def run_python():
    """pythonでCPUを使う処理"""
    l = [0]
    for i in range(1000000):
        l[0] = i

# プロファイル結果はランダムに1分間隔で書かれるので、1分ちょうどだと書かれないことがあるため2分ぐらい回しておく
DURATION_SECS = 120

task = run_python
start = time.monotonic()
while time.monotonic() < start + DURATION_SECS:
    task()

結果がこちらです。それぞれ CPU time, Wall time です。

python で CPU を使う処理: CPU time

python で CPU を使う処理: Wall time

CPU time, Wall time ともに run_python() で 100% 消費していることがわかります。全体の秒数も出ていますが、先述のように 10秒間のプロファイルを取るため、10秒間かかった場合に 100% となっています。

スリープする (CPU を使わない処理)

単にスリープする処理はどうでしょうか。周辺コードは省略します。

def run_sleep():
    """単にスリープする処理"""
    time.sleep(1)

task = run_sleep
# task を 2分間回す (コード省略)

単にスリープする: CPU time

単にスリープする: Wall time

Wall time では run_sleep() で 10秒消費していることがわかりますが、一方、CPU time はスリープでは消費しないため、プロファイラの処理とおぼしきものが出力されています。実質的に CPU を消費した処理がそれだけだったためでしょう。

また、CPU time の全体時間は 10ms となっています。Wall time とは異なり、CPU time の場合は 10秒かかっていなくても 100% になるようです。おそらく実行が記録された関数群のうち、該当の関数が何割を占めているかがパーセンテージとして表示されていると考えられます。

ネイティブコードで CPU を使う処理

Python のライブラリは、速度が必要な箇所はネイティブコードで実装されていることが多いです。ネイティブコードの場合はどう表示されるでしょうか。今回は json.dumps() で試してみます。

# JSON化に使うダミーデータ
JSON_SAMPLE = {
    'foo': 'bar',
    'a': 123,
    'b': 456.789,
}

def run_native():
    """ネイティブコードでCPUを使う処理"""
    for _ in range(100000):
        b = json.dumps(JSON_SAMPLE)

ネイティブコードで CPU を使う処理: CPU time

ネイティブコードで CPU を使う処理: Wall time

CPU time, Wall time とも似たような結果です。

json.dumps() の内部処理として iterencode() までが表示されていますが、これは python コードで、ここからさらにネイティブコードの呼び出しがあります。しかし、ネイティブコードについてはプロファイル結果に表示されないことがわかります。あくまで python の関数のみが表示されます。
また、ネイティブコードの実行時間は呼び出し元の python 関数の実行時間に含まれた形で表示されます。

スレッドで CPU を使う処理

スレッドに関してはどうなるでしょうか。メインスレッドとは別にスレッドを1つ立て、CPU を使う処理を実行してみます。メインスレッドは処理の完了を待つだけとします。

単純化のため、スレッドは 1つだけとしますが、後々複数スレッドの例も試します。

def run_thread():
    """スレッドでCPUを使う処理"""

    def thread_task():
        start = time.monotonic()
        while time.monotonic() < start + 1:  # 1秒間実行
            l = [0]
            for i in range(1000000):
                l[0] = i

    t = threading.Thread(target=thread_task)
    t.start()
    t.join()

スレッドで CPU を使う処理: CPU time

スレッドで CPU を使う処理: Wall time

CPU time ではサブスレッド内の処理が結果に現れています。メインスレッドの処理もあるはずですが、待っているだけでほぼ CPU を使わないため現れていない形です。

一方、Wall time ではメインスレッドの処理のみが結果に現れています。
Cloud Profiler のドキュメントにも記載がありますが、 Wall time プロファイルではメインスレッドのみサポートされています。

async で CPU を使う処理

async を使った非同期処理ではどうなるでしょうか。

def run_async():
    """asyncでCPUを使う処理"""

    async def async_task():
        start = time.monotonic()
        while time.monotonic() < start + 1:  # 1秒間実行
            l = [0]
            for i in range(1000000):
                l[0] = i

    loop = asyncio.get_event_loop()
    loop.run_until_complete(async_task())

async で CPU を使う処理: CPU time

async で CPU を使う処理: Wall time

CPU time, Wall time とも同様の結果で、非同期処理である async_task() が結果に現れています。

async はスレッドの生成は行わず、イベントループを実行しているスレッド(今回の場合メインスレッド)で処理が行われるため、メインスレッドでループを実行する場合と同じになります。

GC の時間はどう表示されるか

python ではメモリ管理に参照カウント及び GC (ガベージコレクション) の両方が採用されています。通常は参照カウントが 0 になるとメモリが解放されますが、データ構造に循環参照がある場合は参照カウントが 0 にならないため、GC の動作により解放されます。

普通に考えると、参照カウントの処理はネイティブコードと同様の扱いになり、 (参照カウントの操作を引き起こした) python 関数の実行時間に含まれるであろうというのは想像がつきますが、GC についてはどうでしょうか。

結論から言うと、GC もネイティブコードと同様の扱いで、GC を引き起こした python 関数の実行時間に含まれるようです。
python の GC は、生存しているオブジェクトの数があるしきい値を超えると呼び出されますが、このチェックが行われるのは新しくオブジェクトを生成しようとした時で、かつ GC はブロッキングで動作するためです。

def run_gc():
    """大量にメモリ確保する処理。GC時間が反映されるか確認したい"""
    for i in range(1000):
        l = [None] * 100000
        l[0] = l # 循環参照を作ることでリファレンスカウントによる解放を防ぐ

GC が発生する処理: CPU time

GC が発生する処理: Wall time

頻繁に GC が起きるコードですが、見ての通り、GC の実行時間はプロファイル結果からはわかりません。 python 関数の実行時間の中に含まれています。
なお Wall time にて unknown という表示が出ているのですが、これが GC に関係するものかどうかは不明です。

複数スレッドで CPU を使う処理

先述の「スレッドで CPU を使う処理」の所ではスレッド数を 1 としました。

Python には GIL (グローバルインタプリタロック) があり、多くの場合複数スレッドがあっても CPU コアを 1つしか使えないのですが、 I/O や一部の CPU負荷の高い処理は GIL を開放するようになっており、複数スレッドで複数コアを利用することができます。

例えば hashlib などはそうです。これを使って、複数スレッドで複数コアを利用するケースを試してみましょう。

# sha256 に使うダミーデータ
HASH_SAMPLE = random.randbytes(1 * 1024 * 1024)

def run_digest():
    """複数スレッドでCPUを使う処理、GILが解放されるケース"""

    def digest_task():
        start = time.monotonic()
        while time.monotonic() < start + 1:  # 1秒間実行
            hashlib.sha256(HASH_SAMPLE).hexdigest()

    ts = [None] * 8
    for i, _ in enumerate(ts):
        ts[i] = threading.Thread(target=thread_task)
        ts[i].start()
    for i, _ in enumerate(ts):
        ts[i].join()

複数スレッドで CPU を使う処理: CPU time

複数スレッドで CPU を使う処理: Wall time

この場合、CPU time で digest_task() が 100% になっていますが、消費時間が 78.87s と、10秒をはるかに超えて約 8倍の値になっています。つまり複数コアを使った場合は CPU time が 10秒を超えることがあります。今回の場合は 8 スレッドあり、8コアをフルに利用したため 10秒 x 8 = 80秒分になったということです。