結論：全体の入口はcumtime、関数自身の重さはtottimeを見る
処理が遅い原因を関数ごとに調べたいなら、標準ライブラリのcProfileで対象の処理だけを計測する。cumtimeは呼び出した先も含めた累積時間、tottimeは子関数を除いたその関数自身の時間である。まずcumtime順で時間のかかる処理のまとまりを探し、次にtottimeと呼び出し回数で、その中のどこを見直すかを絞ると分かりやすい。
呼び出し元のcumtimeが大きくても、その関数の数行を直せば速くなるとは限らない。ほとんどの時間を下位の読込関数や計算関数で使っているかもしれないためである。逆に1回あたりは短くても、同じ変換を何十万回も呼んでいれば全体では大きな負担になる。時間だけでなくncallsを一緒に読むことが、無駄な繰り返しを見つける手掛かりになる。
そのまま動かせる例
例は平方和の計算を8回行い、各回で短い待ち時間を入れる。実データや外部通信は使わず、計算する関数とそれを呼ぶ関数の時間の違いを見られる。標準ライブラリだけで動く。sleepはI/O待ちの性質を説明するための人工的な待機であり、通信性能の測定ではない。計測対象の関数から返った結果も数式で確認している。
以下の出力は実際に一度実行した値である。時刻やOSの負荷によって秒数は変わるので、小数の一致を再現条件にしないでほしい。strip_dirs()でパスを短くし、対象の3関数だけを表示している。表の行番号は保存するコードの行配置で変わる。出力の時間を足し合わせてプログラム全体の時間にしない点にも注意したい。
import cProfile
import pstats
import time
from pstats import SortKey
def calculate(n):
total = 0
for i in range(n):
total += i * i
return total
def batch():
results = []
for _ in range(8):
results.append(calculate(5000))
time.sleep(0.002)
return results
with cProfile.Profile() as profiler:
results = batch()
assert results == [4999 * 5000 * 9999 // 6] * 8
stats = pstats.Stats(profiler).strip_dirs()
rows = {key[2]: value for key, value in stats.stats.items()}
assert rows["calculate"][1] == 8
assert rows["batch"][3] >= rows["calculate"][3]
print("Sorted by cumtime (seconds):")
stats.sort_stats(SortKey.CUMULATIVE).print_stats("batch|calculate|sleep")
print("Sorted by tottime (seconds):")
stats.sort_stats(SortKey.TIME).print_stats("batch|calculate|sleep")
print("calculate calls:", rows["calculate"][1])
実行結果（秒数は実測値。再実行で変動する）
Sorted by cumtime (seconds):
27 function calls in 0.018 seconds
Ordered by: cumulative time
List reduced from 6 to 3 due to restriction <'batch|calculate|sleep'>
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.018 0.018 example.py:12(batch)
8 0.017 0.002 0.017 0.002 {built-in method time.sleep}
8 0.002 0.000 0.002 0.000 example.py:6(calculate)
Sorted by tottime (seconds):
27 function calls in 0.018 seconds
Ordered by: internal time
List reduced from 6 to 3 due to restriction <'batch|calculate|sleep'>
ncalls tottime percall cumtime percall filename:lineno(function)
8 0.017 0.002 0.017 0.002 {built-in method time.sleep}
8 0.002 0.000 0.002 0.000 example.py:6(calculate)
1 0.000 0.000 0.018 0.018 example.py:12(batch)
calculate calls: 8
二つの並べ替えを比較する
cumtime順では、batchの中でcalculateとsleepを呼んでいるため、その累積時間が大きい。一方、batch自身のtottimeはループやリストへの追加などに使った時間である。tottime順へ切り替えると、待機や実際の計算へ視線を移しやすい。同じ計測結果を並べ替えているだけなので、2回目の表が別の実行の結果というわけではない。
表にはpercallが二つ現れる。一つはtottimeを呼び出し回数で割った値、もう一つはcumtimeを原始呼び出し回数で割った値である。再帰呼び出しのある関数ではncallsに二つの数が表示されることもある。今回の非再帰の例ではcalculateが8回と読めればよい。細部を理解する前に、どのまとまりに時間が偏るかを見るだけでも十分役に立つ。
調べる入力と範囲を絞る
実際の処理では、モジュールのimportや初回のキャッシュ作成も計測へ含めるのかを決める。日常的な1回の実行速度を知りたいなら初回費用も重要だが、何度も呼ぶ関数の改善ならその部分を切り出す方が原因を追いやすい。都合のよい小さな入力だけで測らず、問題が起きるデータの形や大きさを保った代表例を用意しよう。
外部への保存、描画、通信待ち、Python以外で実装された計算が混ざると、関数単位の結果だけでは内部まで分からない場合がある。必要に応じて処理を読み込み・前処理・計算・保存へ分け、範囲を狭めて再計測する。プロセスを分けた仕事の実行時間も、親のプロファイルだけで全て見えていると考えないようにしたい。
高速化前後は正しさをそろえて比較する
cProfileはどこで時間を使うかを調べる道具であり、厳密なマイクロベンチマークを目的とするものではない。記録の処理自体が負荷となり、Pythonの関数呼び出しが多い実装ほど影響を受ける。改善案が固まったら、結果が同じことを確認したうえで、通常実行やtimeitなど目的に合う方法で複数回比較するとよい。
一番上に出た関数を無条件に書き換えるより、不要な呼び出しを減らす、同じ読込を繰り返さない、入力の形を改善するといった設計上の変更を検討したい。表示桁が0.000だから費用がゼロという意味でもない。小さな差を大げさに解釈せず、全体の待ち時間を利用者にとって意味のある程度まで減らせるかを判断基準にしよう。
確認環境と参考資料
例はLinux・CPython 3.12.14で実行した。掲載した出力はこの環境での結果である。公式資料のstable版や最新版は更新されるため、手元のバージョンと対応する仕様も確認してほしい。
- Python公式：プロファイラ（2026年10月2日参照）
関連項目：tracemallocでメモリが増えた場所を調べる ／ スレッドとプロセスはどう選ぶ？待ち時間と計算負荷で考える