Python 実行スクリプトのプロファイルを取るには cProfile モジュールを -m を使って実行する。
$ python -m cProfile -s tottime spam.py 42
すると、こんな出力が出る。
1794060 function calls (1791259 primitive calls) in 7.057 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
9715 3.492 0.000 5.249 0.000 hoge.py:7(heavy_function)
30910 0.413 0.000 0.413 0.000 {method 'fuga' of '_foo.bar' objects}
30910 0.282 0.000 5.509 0.000 foo.py:365(execute)
(以下略)
最初の行は総計でどれだけ関数呼び出しがあったか、何秒掛かったかが表示されている。
-s tottime を指定したので、下の表は tottime の大きい順にソートされて表示される。
tottime はその関数自体で何秒費やしたかという合計時間(total time)。
ここでは hoge.py の7行目にある heavy_function が9715回呼ばれて3.492秒掛かったのが一番。
heavy_function というわりには1回あたりはせいぜい0.3ミリ秒だが、まあここが速くなればプログラムの実行が早くなるだろうという部分ではある。
ちなみに上の「1回あたりはせいぜい0.3ミリ秒」という情報は tottime の隣の percall に表示されていることになっているのだが、単位が秒のため表示桁の制約上 0.000 としか表示されていない。
大概の場合この percall 欄は役に立たない。
2行目の関数名の欄が {method 'fuga' of '_foo.bar' objects} という表示で行番号が出ていないのは、C のライブラリが呼び出されている部分。
3行目と呼び出し回数が同じなので、おそらく3行目の foo.py にある execute 関数がこのライブラリを呼び出しているのだろう。
これで大体出力の読み方も解ったと思うが、もう一つ cumtime が気になる人もいるかもしれない。
これは cumulative time つまり累積時間のことで関数から更に呼ばれた関数での時間もこみこみで出した消費時間のことを意味する。
場合によっては tottime より cumtime を見たいこともあるかもしれない。
そうしたときは -s cumtime を -s tottime の代わりに指定すれば cumtime 順で出力される。
参考:
