Pythonプロファイリング：cProfileとPy-Spyで「遅いコード」を特定・解決するテクニック – ITFROMZERO

Table of Contents

なぜコードが遅いのか？推測を捨て、計測しよう

よくあるシナリオです。データ処理スクリプトを書き、10件のレコードで試すとスムーズに動く。しかし、本番環境で100万件のデータを投入した途端、システムが突然「フリーズ」する。反射的に「遅そう」と感じるコードを修正したくなりますが、新人の頃の私もそうでした。結果として、あちこち修正しても速度は変わらず、むしろバグを増やすだけでした。

ドナルド・クヌースはかつて「早すぎる最適化は諸悪の根源である」と言いました. 推測する代わりに、プロファイリング（Profiling）が必要です。これは、どの関数が最も時間を消費しているか、あるいはどの行がCPUを占有しているかを正確に特定するための分析手法です。

私が愛用している2つのツールを紹介します。Python標準のcProfileと、稼働中のアプリケーションに強力なPy-Spyです。

実践のためのツールインストール

cProfileは標準ライブラリなので追加のインストールは不要ですが、結果をグラフで視覚的に確認するためにsnakevizをインストールしておきましょう。

稼働中のアプリケーションを中断せずに調査したい場合は、Py-Spyが最適です。Rustで書かれており、非常に軽量で、システムへのオーバーヘッドもほとんどありません。

# Py-Spyをインストールしてプロセスを監視する
pip install py-spy

# snakevizをインストールしてグラフを視覚化する
pip install snakeviz

注意：LinuxやmacOSでは、実行中のプロセスに介入するためにpy-spyにsudo権限が必要な場合があります。

cProfileでコード内の各関数を調査する

cProfileは決定論的プロファイラです。すべての関数呼び出しイベントを極めて詳細に記録します。唯一の欠点は、継続的にログを記録するため、コードの実行速度が2〜5倍ほど遅くなる可能性があることです。

方法1：コマンドラインから直接実行する

heavy_script.pyというファイルがあるとします。通常通り実行する代わりに、以下のコマンドを使用します。

python -m cProfile -s cumulative heavy_script.py

-s cumulativeフラグを使用すると、関数とその子関数の合計実行時間順に結果をソートできます。以下の項目に注目してください。

ncalls: 関数の呼び出し回数。
tottime: その関数自体での実行時間。
cumtime: 関数に入ってから抜けるまでの合計時間。

方法2：コードに埋め込んで特定のロジックをチェックする

複雑なロジックの一部だけをテストしたい場合は、コード内で直接Profileオブジェクトを使用します。

import cProfile
import pstats

def process_data():
    # 1,000万件の要素を処理する重いコードを想定
    return sum([i**2 for i in range(10000000)])

with cProfile.Profile() as pr:
    process_data()

stats = pstats.Stats(pr)
stats.sort_stats(pstats.SortKey.TIME).print_stats(10)

以前、テキスト処理スクリプトをデバッグしていた際、正規表現の間違いで無限ループが起きていると思い込んでいました。しかし、cProfileで調査したところ、ループ内でファイルを何度も開閉していたことが原因だと判明しました。ちなみに、正規表現を素早くテストしたい場合は、時間を節約するためにtoolcraft.appの正規表現テスターをよく使っています。

Py-Spy：稼働中のアプリケーション（Production）向けのソリューション

cProfileの弱点は、スクリプトを再起動する必要があることです。しかし、FastAPIのAPIが稼働中でCPU使用率が100%に達している場合、デバッグのために停止させるわけにはいきません。そこでPy-Spyの出番です。

‘top’コマンドのようにライブ監視する

PID（プロセスID）を指定して、どの関数がCPUを消費しているかをリアルタイムで監視できます。

# pythonプロセスのPIDを探す
ps aux | grep python

# ライブモニタリングを表示
py-spy top --pid 1234

OSのtopコマンドと同様に、リソースを占有している関数のリストがリアルタイムで表示されます。

Flame Graphを作成し、ボトルネックを一目で把握する

Flame Graph（フレームグラフ）は、ボトルネックを見つけるための最速の方法です。ブロックの幅が広いほど、その関数の実行に時間がかかっていることを示します。

py-spy record -o profile.svg --pid 1234

約30秒間実行した後、Ctrl+Cを押します。profile.svgファイルをブラウザで開くと、パフォーマンスの全体像が表示されます。以前、このグラフを使って、コードの遅さはPythonのロジックではなく、データベースクエリのインデックス不足が原因であることを上司に証明したことがあります。

原因特定後の最適化のヒント

データが得られたら、次は最適化です。私がよく遭遇する3つの典型的なミスを紹介します：

1. 不適切なデータ構造での検索

検索関数でncallsが多くtottimeが高い場合は、データ構造を見直してください。listでの検索（$O(n)$）からsetやdict（$O(1)$）に変更するだけで、コードが数百倍速くなることもあります。

2. ライブラリの誤用

Pythonの純粋なリストで巨大な配列を処理するのは非常に遅いです。NumPyやPandasの利用を検討しましょう。これらのライブラリはC/C++ベースで動作するため、通常のPythonのループよりも圧倒的に高いパフォーマンスを発揮します。

3. I/OバウンドとCPUバウンドの混同

cumtimeは大きいのにtottimeが極端に小さい場合、コードはI/O待ち（API呼び出し、DB読み取りなど）の状態にあります。この場合、CPUアルゴリズムを最適化しても意味がありません。asyncioに切り替えるか、ワーカー数を増やして待ち時間を有効活用する必要があります。

プロファイリングは一度きりの作業ではありません。大きな機能を追加するたびに習慣化しましょう。わずか15分の計測で、無駄なコード修正に費やす何時間もの時間を節約できます。