これは、なにをしたくて書いたもの?
Pythonには標準で、cProfileとprofileというプロファイリングツールがあるようです。
27.4. Python プロファイラ — Python 3.6.12 ドキュメント
こちらを、ちょっと試してみようと思いまして。
環境
今回の環境は、こちらです。
$ lsb_release -a No LSB modules are available. Distributor ID: Ubuntu Description: Ubuntu 18.04.2 LTS Release: 18.04 Codename: bionic $ python3 -V Python 3.6.7
サンプルプログラム
計測対象のサンプルプログラムは、こちら。
profiling-example.py
def fib(n): if n == 0: return 0 elif n == 1: return 1 else: return fib(n - 1) + fib(n - 2) def heavy_loop(n = 500000000): for i in range(n): calc() print("executed %d loop" % n) def calc(): 1 + 2 def hello_world(): print("Hello World!!") def task(fib_num, heavy_loop_num): print("fib(%d) = %d" % (fib_num,fib(fib_num))) heavy_loop(heavy_loop_num) hello_world() task(35, 10000000)
すごくわざとらしいですが、とりあえずこんな感じで。
まずは、このプログラムをtimeコマンド経由で実行して計測してみます。
$ time python3 profiling-example.py fib(35) = 9227465 executed 10000000 loop Hello World!! real 0m3.746s user 0m3.737s sys 0m0.008s
4秒近くかかるようです。この数字をちょっと覚えておきましょう。
cProfile
cProfileは、ドキュメントによるとC言語で書かれた拡張モジュールで、オーバーヘッドが少ないらしいです。長時間実行される
プログラムのプロファイルに向くそうな。
リファレンスマニュアル -- profile と cProfile
実行方法は、スクリプト起動時に仕込む方法と、プログラム内でモジュールとして使う方法の2つがあります。
スクリプトの起動時に仕込む場合は、こちら。
$ python -m cProfile [-o output_file] [-s sort_order] myscript.py
というわけで、用意したサンプルプログラムで試してみましょう。
$ python3 -m cProfile profiling-example.py fib(35) = 9227465 executed 10000000 loop Hello World!! 39860712 function calls (10000010 primitive calls) in 7.179 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 7.179 7.179 profiling-example.py:1(<module>) 29860703/1 5.716 0.000 5.716 5.716 profiling-example.py:1(fib) 10000000 0.437 0.000 0.437 0.000 profiling-example.py:15(calc) 1 0.000 0.000 0.000 0.000 profiling-example.py:18(hello_world) 1 0.000 0.000 7.179 7.179 profiling-example.py:21(task) 1 1.026 1.026 1.463 1.463 profiling-example.py:9(heavy_loop) 1 0.000 0.000 7.179 7.179 {built-in method builtins.exec} 3 0.000 0.000 0.000 0.000 {built-in method builtins.print} 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
プログラムの終了時に、各関数のプロファイリング結果が表示されました。
ここで、各項目の意味は以下になります。
- ncalls … 呼び出し回数
- tottime … 関数で消費された合計時間(サブ関数の呼び出しは除外)
- percall … tottime / ncalls
- cumtime … 関数で消費された累積時間(サブ関数の呼び出し含む)
- percall … cumtime / 呼び出し回数
- filename:lineno(function) … 関数のファイル名、行番号、関数名
実行時間は、7秒を越えましたね。
また、出力内容はソートできるようです。ソートで指定できる項目は、以下を参照してください。
cumulative(関数の累積時間)でソートしてみましょう。
$ python3 -m cProfile -s cumulative profiling-example.py fib(35) = 9227465 executed 10000000 loop Hello World!! 39860712 function calls (10000010 primitive calls) in 7.359 seconds Ordered by: cumulative time ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 7.359 7.359 {built-in method builtins.exec} 1 0.000 0.000 7.359 7.359 profiling-example.py:1(<module>) 1 0.000 0.000 7.359 7.359 profiling-example.py:21(task) 29860703/1 5.811 0.000 5.811 5.811 profiling-example.py:1(fib) 1 1.068 1.068 1.548 1.548 profiling-example.py:9(heavy_loop) 10000000 0.480 0.000 0.480 0.000 profiling-example.py:15(calc) 3 0.000 0.000 0.000 0.000 {built-in method builtins.print} 1 0.000 0.000 0.000 0.000 profiling-example.py:18(hello_world) 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
tottime(関数の内部時間)でソートした場合。
$ python3 -m cProfile -s tottime profiling-example.py fib(35) = 9227465 executed 10000000 loop Hello World!! 39860712 function calls (10000010 primitive calls) in 7.337 seconds Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 29860703/1 5.850 0.000 5.850 5.850 profiling-example.py:1(fib) 1 1.032 1.032 1.488 1.488 profiling-example.py:9(heavy_loop) 10000000 0.456 0.000 0.456 0.000 profiling-example.py:15(calc) 3 0.000 0.000 0.000 0.000 {built-in method builtins.print} 1 0.000 0.000 7.337 7.337 profiling-example.py:21(task) 1 0.000 0.000 7.337 7.337 profiling-example.py:1(<module>) 1 0.000 0.000 7.337 7.337 {built-in method builtins.exec} 1 0.000 0.000 0.000 0.000 profiling-example.py:18(hello_world) 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
cProfileの結果を可視化してみる
cProfileでの出力結果は、RunSnakeRunを使うことで可視化することができる…らしいのですが、どうもPython 2系でしか
動かない感じがします。
RunSnakeRun Python (c)Profile Viewer
代わりに、SnakeVizというものが使えそうなのでこちらを試してみました。
cProfileを「-o」付きで実行して、結果をファイルに保存します(「-o」で結果を出力するファイル名を指定します)。
$ python3 -m cProfile -o profiling.stats profiling-example.py fib(35) = 9227465 executed 10000000 loop Hello World!!
この結果ファイルは、バイナリフォーマットみたいです。
SnakeVizをインストール。
$ python3 -m venv venv $ . venv/bin/activate $ pip3 install snakeviz
インストールされたSnakeViz。
$ pip3 freeze ... snakeviz==2.0.0 ...
プロファイリング結果を引数に与えて起動すると、
$ snakeviz profiling.stats
ブラウザが起動して描画結果が表示されます。
描画されている部分にマウスオーバーすると、左側に情報が表示されますし
クリックするとドリルダウンしていくこともできます。
APIで使う場合
少しだけ、cProfileをAPIで使う場合も試してみましょう。
ソースコードを修正することになるので、1度ファイルをコピー。
$ cp profiling-example.py profiling-example-with-cprofile.py
こんな感じで使います。
profiling-example-with-cprofile.py
import cProfile def fib(n): if n == 0: return 0 elif n == 1: return 1 else: return fib(n - 1) + fib(n - 2) 〜省略〜 def task(fib_num, heavy_loop_num): print("fib(%d) = %d" % (fib_num,fib(fib_num))) heavy_loop(heavy_loop_num) hello_world() cProfile.run('task(35, 10000000)')
プロファイリングの実行は、関数の呼び出しを文字列で与えることで行うんですね。
ファイル名を与えると、「-o」オプションのように結果をファイルに出力することができます。
cProfile.run('task(35, 10000000)', "profiling-by-api.stats")
もっと細かく制御したい場合はProfileクラスを使ったり、結果を格納したStatsクラスを利用することもできるようです。
class profile.Profile(timer=None, timeunit=0.0, subcalls=True, builtins=True)
profile
profileは、cProfileを模倣して作られた、Pythonで書かれたプロファイリングツールです。
実行方法もほとんど同じなので、スクリプト起動時に仕込んでみます。
$ python3 -m profile profiling-example.py fib(35) = 9227465 executed 10000000 loop Hello World!! 39860713 function calls (10000011 primitive calls) in 57.583 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 57.583 57.583 :0(exec) 3 0.000 0.000 0.000 0.000 :0(print) 1 0.001 0.001 0.001 0.001 :0(setprofile) 1 0.000 0.000 57.583 57.583 profile:0(<code object <module> at 0x7fe9d93439c0, file "profiling-example.py", line 1>) 0 0.000 0.000 profile:0(profiler) 1 0.000 0.000 57.583 57.583 profiling-example.py:1(<module>) 29860703/1 44.234 0.000 44.234 44.234 profiling-example.py:1(fib) 10000000 6.194 0.000 6.194 0.000 profiling-example.py:15(calc) 1 0.000 0.000 0.000 0.000 profiling-example.py:18(hello_world) 1 0.000 0.000 57.583 57.583 profiling-example.py:21(task) 1 7.154 7.154 13.349 13.349 profiling-example.py:9(heavy_loop)
プロファイリング結果が出ましたが、実行時間が57秒になりました…。めちゃくちゃ遅くなりますね…。
cProfileと同様にAPIとしても扱うことができます。インターフェースを模倣しているので、APIドキュメントは同じです。
リファレンスマニュアル -- profile と cProfile
ちょっと試してみます。元のファイルをコピーして…
$ cp profiling-example.py profiling-example-with-profile.py
変更。
profiling-example-with-profile.py
import profile def fib(n): if n == 0: return 0 elif n == 1: return 1 else: return fib(n - 1) + fib(n - 2) 〜省略〜 def task(fib_num, heavy_loop_num): print("fib(%d) = %d" % (fib_num,fib(fib_num))) heavy_loop(heavy_loop_num) hello_world() profile.run('task(35, 10000000)')
実行。
$ python3 profiling-example-with-profile.py fib(35) = 9227465 executed 10000000 loop Hello World!! 39860713 function calls (10000011 primitive calls) in 57.573 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 57.572 57.572 :0(exec) 3 0.000 0.000 0.000 0.000 :0(print) 1 0.000 0.000 0.000 0.000 :0(setprofile) 1 0.000 0.000 57.572 57.572 <string>:1(<module>) 0 0.000 0.000 profile:0(profiler) 1 0.000 0.000 57.573 57.573 profile:0(task(35, 10000000)) 1 7.077 7.077 13.205 13.205 profiling-example-with-profile.py:11(heavy_loop) 10000000 6.128 0.000 6.128 0.000 profiling-example-with-profile.py:17(calc) 1 0.000 0.000 0.000 0.000 profiling-example-with-profile.py:20(hello_world) 1 0.000 0.000 57.572 57.572 profiling-example-with-profile.py:23(task) 29860703/1 44.367 0.000 44.367 44.367 profiling-example-with-profile.py:3(fib)
やっぱり、めちゃくちゃ遅いですね…。
通常は、cProfileを使うんでしょうね。