Pythonアプリが急に遅くなって、原因がまったくわからないとき
6ヶ月前、私は1バッチあたり約50,000件のレコードを処理するデータパイプラインのデバッグをしていました。開発中の小さなデータセットでは問題なく動いていたのに、本番環境に投入したら40秒以上かかるようになってしまいました――これは完全に許容範囲外です。最初の直感はループを書き直すことでした。2日間、的外れな部分を最適化し続けた末に、自分がただ当てずっぽうをしていただけだと気づきました。
その経験が、きちんとプロファイリングを学ぶきっかけになりました。無駄にした2日間がそう教えてくれたのです。ボトルネックを推測するのは戦略ではありません――測定することこそが正解です。このガイドでは、cProfile（Pythonの標準ライブラリに組み込み済み）とVizTracer（モダンなフレームグラフプロファイラー）の2つのツールを、今日から動かせる実際のコード例とともに紹介します。
基本概念：プロファイリングが実際に何をするのか
プロファイラーはコードを計測します――一定間隔でサンプリングするか、すべての関数呼び出しにフックを仕掛けるかで――どこでどれだけの時間が費やされているかを記録します。その出力から、どの関数がCPU時間を消費しているか、何回呼ばれているか、コールツリー全体の累積コストがどのように見えるかが正確にわかります。
2つのプロファイリングモード
- 決定論的プロファイリング（cProfile）: すべての関数呼び出しとリターンにフックします。非常に正確ですが、若干のオーバーヘッドが生じます――プロファイリング中は10〜50%の速度低下が見込まれます。
- サンプリングプロファイリング: 定期的に起動して現在のコールスタックを記録します。オーバーヘッドが低い分、高速な関数では精度が落ちます。
cProfileは決定論的アプローチを使用します。VizTracerも同様ですが、その上に豊富な可視化レイヤーが追加されています。これにより、何が遅いかだけでなく、なぜ遅いのかを理解するのがずっと簡単になります。
読むべき重要なメトリクス
プロファイリングの出力を確認するとき、最も重要な3つの数値があります：
- ncalls — 関数が呼ばれた回数。予想外に多い回数はループの問題を示していることが多いです。
- tottime — 関数内で費やされた合計時間（サブ呼び出しを除く）。純粋な計算のボトルネックを捉えます。
- cumtime — すべてのサブ呼び出しを含む累積時間。関数がコーディネーター役の場合は、まずここを最適化します。
ハンズオン実践
ステップ1 — cProfileでプロファイリングする
インストール不要です。意図的なボトルネックを含むテストスクリプトを作成します：
# slow_app.py
import time
def fetch_data(n):
result = []
for i in range(n):
result.append(expensive_lookup(i))
return result
def expensive_lookup(x):
# 遅い処理をシミュレート — DBコールや重い計算など
time.sleep(0.001)
return x * x
def process(data):
return [d for d in data if d % 2 == 0]
def main():
data = fetch_data(200)
result = process(data)
print(f"完了: {len(result)} 件")
if __name__ == "__main__":
main()
コマンドラインからcProfileを実行します：
python -m cProfile -s cumtime slow_app.py
-s cumtimeフラグは累積時間で並べ替えるため、最も問題のある箇所が先頭に表示されます。次のような出力が得られます：
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.214 0.214 slow_app.py:18(main)
1 0.001 0.001 0.213 0.213 slow_app.py:3(fetch_data)
200 0.001 0.000 0.212 0.001 slow_app.py:9(expensive_lookup)
200 0.211 0.001 0.211 0.001 {built-in method time.sleep}
一目瞭然です：expensive_lookupが200回呼ばれており、time.sleepがほぼすべての実行時間を消費しています。実際の現場では、これはほぼ常にループ内のキャッシュされていないデータベースクエリや繰り返しのHTTPリクエストが原因です。
ステップ2 — 詳細分析のためにプロファイルデータを保存する
大規模なコードベースの場合、プロファイルを保存してインタラクティブに調べることができます：
python -m cProfile -o profile_output.prof slow_app.py
python -m pstats profile_output.prof
または、コード内の特定の関数をプロファイリングする方法もあります：
import cProfile
import pstats
import io
def profile_this():
pr = cProfile.Profile()
pr.enable()
main() # 実際の関数をここで呼ぶ
pr.disable()
s = io.StringIO()
ps = pstats.Stats(pr, stream=s).sort_stats('cumulative')
ps.print_stats(15) # 上位15件を表示
print(s.getvalue())
profile_this()
ステップ3 — VizTracerで可視化する
cProfileは何が遅いかを見つけるのに優れています。VizTracerはいつ、なぜ遅いのかを示してくれます――特に非同期コード、マルチスレッドアプリ、深くネストされたコールチェーンで威力を発揮します。
まずインストールします：
pip install viztracer
同じスクリプトに対して実行します：
viztracer slow_app.py
VizTracerは作業ディレクトリにresult.jsonを書き出します。次のコマンドで開きます：
vizviewer result.json
インタラクティブなフレームグラフが表示されます。各バーは関数呼び出しを表し、幅は時間を、ネストはコールスタックを示します。任意のセクションをズームインし、ホバーすると正確なタイミングが確認でき、パターンがすぐに見えてきます――200個の全く同一の呼び出しが一列に並んでいれば、それは明らかに何かがおかしいサインです。
ステップ4 — 重要な部分だけをプロファイリングする
アプリケーション全体をプロファイリングするとノイズが増えます。VizTracerはコンテキストマネージャーを使ったピンポイントのプロファイリングをサポートしています：
from viztracer import VizTracer
with VizTracer(output_file="targeted.json") as tracer:
data = fetch_data(200) # このセクションのみをプロファイル
絞り込んだトレースは小さく保たれます――多くの場合5MB未満――読みやすいです。実際のコードベースが1秒間に何千もの関数呼び出しを発生させるようになれば、これは非常に重要になります。
ステップ5 — ボトルネックを修正して確認する
元のパイプライン問題に戻ります：N+1スタイルの呼び出しパターンの修正は、ほぼ常にキャッシュかバッチ処理です。修正後のバージョンを示します：
from functools import lru_cache
@lru_cache(maxsize=1024)
def expensive_lookup(x):
time.sleep(0.001)
return x * x
実際の本番環境では、これはSQLAlchemyの遅延ロード問題でした――各ループのイテレーションが個別のSELECTを発行していたのです。修正方法は.options(joinedload(...))を使った積極的ロードへの切り替えでした。修正前にプロファイリング、修正後にプロファイリング、数値を比較する。修正が実際に効いたかどうかを確認する唯一の確実な方法はこれだけです。
修正後にcProfileを再度実行します：
python -m cProfile -s cumtime slow_app.py
lru_cacheを使用すると、同じ入力での2回目の実行ではexpensive_lookupのtottimeがほぼゼロに近づきます。キャッシュが繰り返しの呼び出しを吸収するためです。
クイックリファレンス：どのツールをいつ使うか
- cProfile: 初回の分析、CI統合、スクリプト処理、純粋な関数ボトルネックの特定
- VizTracer: コールチェーンの把握、非同期・マルチスレッドの問題、チームへの共有（ビジュアルは何千行ものstats出力に勝る）
- 両方を組み合わせる: cProfileで問題のモジュールを絞り込み、VizTracerでその内部のパターンを理解する
まとめ：まずプロファイリング、最適化はその後で
あのパイプラインの間違った部分を2日間最適化し続けた経験が、それ以来ずっと破っていないルールを教えてくれました：プロファイラーのトレースなしにパフォーマンスクリティカルなコードに手を加えてはならない。ボトルネックはほぼ常に、あなたが想定していた場所にはありません。
cProfileはゼロ依存で常に使えます――実行しない言い訳はありません。VizTracerは、プロファイリングの出力を実行した本人だけでなくチーム全体が読めるようにする視覚的なコンテキストを付け加えてくれます。手軽にスキャンするならcProfileから始めましょう。なぜそうなっているのかを説明する必要があるとき、またはコールグラフが複雑すぎてテキスト出力が意味をなさなくなったとき、VizTracerの出番です。
一点、強調しておきたいことがあります：本番環境のデータ量に近いデータでプロファイリングしてください。10件のレコードを処理するスクリプトは、50,000件を処理するものとは全く異なる挙動をします。ボトルネックはスケールしてはじめて姿を現します。
