CLOVER🍀

That was when it all began.

Python標準のcProfile、profileを使ってプロファイリングを試す

これは、なにをしたくて書いたもの?

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秒を越えましたね。

また、出力内容はソートできるようです。ソートで指定できる項目は、以下を参照してください。

sort_stats(*keys)

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というものが使えそうなのでこちらを試してみました。

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

ブラウザが起動して描画結果が表示されます。

f:id:Kazuhira:20190413171211p:plain

f:id:Kazuhira:20190413171223p:plain

描画されている部分にマウスオーバーすると、左側に情報が表示されますし

f:id:Kazuhira:20190413171435p:plain

クリックするとドリルダウンしていくこともできます。

f:id:Kazuhira:20190413171513p:plain

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)

Stats クラス

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を使うんでしょうね。