この記事では、Python で関数やスクリプトファイルをプロファイリングする方法を解説します。
プロファイリングとは、関数などのプログラム各所の呼び出し回数や処理にかかった時間などを収集し、分析することを言います。また、分析された統計情報を プロファイル、プロファイリングする人やアプリなどを プロファイラ と呼びます。
なんか処理が遅いなっと思ったらプロファイリングすることで問題の箇所を特定することができます。めちゃ便利ですね！
それでは、プロファイリングする方法を見ていきましょう！
プロファイリングでは以下のような情報を収集します。どのような情報が記載されているか確認してきましょう。
9 function calls (7 primitive calls) in 3.010 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 3.009 3.009 <string>:1(<module>)
3/1 0.000 0.000 3.009 3.009 main.py:6(func)
1 0.000 0.000 3.010 3.010 {built-in method builtins.exec}
3 3.009 1.003 3.009 1.003 {built-in method time.sleep}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}最初の行
最初の行では、関数を呼び出した回数と合計処理時間が記述されています。
[関数を呼び出した回数] function calls ([再帰しなかった呼び出し回数] primitive calls) in [かかった秒数] seconds上記の統計情報では、関数を 9回呼び出して測定し、その内 7回再帰しない関数を呼び出して 3.010秒かかりました。
次の行
次の行では、統計情報のソート方法が書かれています。
Ordered by: [ソート方法]列の見出し
列には以下のような情報が記載されています。
| ncalls | 呼び出し回数。3/1 となっている箇所は 再帰/通常。 |
|---|---|
| tottime | 関数に消費された合計時間。関数内で呼び出された関数の処理時間は除外されている。 |
| percall | 1度の呼び出しでかかった時間(tottime / ncalls)。 |
| cumtime | 関数内で呼び出された関数の処理も含めた合計時間。再帰関数も正確に測定可能。 |
| percall | 1度の呼び出しでかかった時間。(cumtime / 通常の呼び出し回数) |
| filename:lineno(function) | 関数のファイル名:行番号(関数名) |
どのような情報が収集され、どのように表示されるか確認することができました。
プロファイリングするにはプロファイラを使えばいいのですが、Python には 2つの標準ライブラリが用意されています。
cProfileモジュール
cProfile は、C言語で書かれている拡張モジュールです。オーバヘッドが少ないので基本的にこちらのモジュールが推奨されています。
profileモジュール
profile は、Python で書かれているモジュールです。オーバーヘッドは多いですが機能を拡張したいときにはこちらのモジュールの方が簡単です。
この記事では、cProfileモジュール を使って解説していきます。
では次にプロファイラを使ってプロファイリングする方法を見ていきましょう。
任意の関数を測定するには cProfileモジュール の run()関数 を使います。
cProfile.run(command, filename=None, sort=- 1)以下のような引数が定義されています。
| command | 実行する関数を文字列で指定。 |
|---|---|
| filename | 出力先を指定できる。デフォルトは標準出力。 |
| sort | ソート方法を指定できる。 |
例えば、自作関数の func() を測定したい場合は以下のようにします。
import time
import cProfile
def func(sec):
time.sleep(sec)
cProfile.run('func(1)')実行結果
5 function calls in 1.004 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 1.004 1.004 <string>:1(<module>)
1 0.000 0.000 1.004 1.004 main.py:4(func)
1 0.000 0.000 1.004 1.004 {built-in method builtins.exec}
1 1.004 1.004 1.004 1.004 {built-in method time.sleep}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}複数行文字列などを使って複数の関数を測定可能。
import time
import cProfile
def func(sec):
time.sleep(sec)
cProfile.run('''func(1)
func(0.5)''')実行結果
7 function calls in 1.508 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 1.508 1.508 <string>:1(<module>)
2 0.000 0.000 1.508 0.754 main.py:4(func)
1 0.000 0.000 1.508 1.508 {built-in method builtins.exec}
2 1.508 0.754 1.508 0.754 {built-in method time.sleep}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}呼び出し回数と処理時間が増えているのが分かります。
コマンドラインからスクリプトファイルを測定することができます。
python -m cProfile スクリプト名以下のようなオプションが用意されています。
| -o output_file | 結果を output_file に書き出します。 |
|---|---|
| -s sort_order | ソートを指定できます。 |
それでは、簡単なスクリプトファイルを測定してみます。
main.py
import time
import cProfile
def func(sec):
time.sleep(sec)
func(1)コマンドラインで以下のように実行します。
$ python3 -m cProfile main.pyすると以下のように統計情報がずらっと表示されます。
254 function calls (253 primitive calls) in 1.006 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.001 0.001 <frozen importlib._bootstrap>:1002(_find_and_load)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:112(release)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:152(__init__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:156(__enter__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:160(__exit__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:166(_get_module_lock)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:185(cb)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:220(_call_with_frames_removed)
17 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:231(_verbose_message)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:35(_new_module)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:351(__init__)
2 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:385(cached)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:398(parent)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:406(has_location)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:486(_init_module_attrs)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:558(module_from_spec)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:58(__init__)
1 0.000 0.000 0.001 0.001 <frozen importlib._bootstrap>:659(_load_unlocked)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:736(find_spec)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:811(find_spec)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:87(acquire)
3 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:874(__enter__)
3 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:878(__exit__)
1 0.000 0.000 0.001 0.001 <frozen importlib._bootstrap>:901(_find_spec)
1 0.000 0.000 0.001 0.001 <frozen importlib._bootstrap>:967(_find_and_load_unlocked)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:1006(__init__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:1031(get_filename)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:1036(get_data)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:1077(path_stats)
16 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:121(_path_join)
16 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:123(<listcomp>)
2 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:127(_path_split)
4 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:129(<genexpr>)
4 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:1337(_path_importer_cache)
5 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:135(_path_stat)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:1374(_get_spec)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:1406(find_spec)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:145(_path_is_mode_type)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:1500(_get_spec)
3 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:1505(find_spec)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:154(_path_isfile)
2 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:361(cache_from_source)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:491(_get_cached)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:523(_check_name_wrapper)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:560(_classify_pyc)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:593(_validate_timestamp_pyc)
3 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:64(_relax_case)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:645(_compile_bytecode)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:696(spec_from_file_location)
3 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:79(_unpack_uint32)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:841(create_module)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:844(exec_module)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap_external>:916(get_code)
1 0.000 0.000 0.000 0.000 cProfile.py:27(Profile)
1 0.000 0.000 0.000 0.000 cProfile.py:3(<module>)
1 0.000 0.000 1.006 1.006 main.py:1(<module>)
1 0.000 0.000 1.005 1.005 main.py:4(func)
1 0.000 0.000 0.000 0.000 {built-in method _imp._fix_co_filename}
5 0.000 0.000 0.000 0.000 {built-in method _imp.acquire_lock}
1 0.000 0.000 0.000 0.000 {built-in method _imp.is_builtin}
1 0.000 0.000 0.000 0.000 {built-in method _imp.is_frozen}
5 0.000 0.000 0.000 0.000 {built-in method _imp.release_lock}
2 0.000 0.000 0.000 0.000 {built-in method _thread.allocate_lock}
2 0.000 0.000 0.000 0.000 {built-in method _thread.get_ident}
1 0.000 0.000 0.000 0.000 {built-in method builtins.__build_class__}
2/1 0.000 0.000 1.006 1.006 {built-in method builtins.exec}
6 0.000 0.000 0.000 0.000 {built-in method builtins.getattr}
5 0.000 0.000 0.000 0.000 {built-in method builtins.hasattr}
6 0.000 0.000 0.000 0.000 {built-in method builtins.isinstance}
4 0.000 0.000 0.000 0.000 {built-in method builtins.len}
2 0.000 0.000 0.000 0.000 {built-in method builtins.max}
3 0.000 0.000 0.000 0.000 {built-in method from_bytes}
1 0.000 0.000 0.000 0.000 {built-in method io.open_code}
1 0.000 0.000 0.000 0.000 {built-in method marshal.loads}
3 0.000 0.000 0.000 0.000 {built-in method posix.fspath}
1 0.000 0.000 0.000 0.000 {built-in method posix.getcwd}
5 0.000 0.000 0.000 0.000 {built-in method posix.stat}
1 1.005 1.005 1.005 1.005 {built-in method time.sleep}
1 0.000 0.000 0.000 0.000 {method '__exit__' of '_io._IOBase' objects}
2 0.000 0.000 0.000 0.000 {method '__exit__' of '_thread.lock' objects}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
1 0.000 0.000 0.000 0.000 {method 'endswith' of 'str' objects}
2 0.000 0.000 0.000 0.000 {method 'get' of 'dict' objects}
18 0.000 0.000 0.000 0.000 {method 'join' of 'str' objects}
1 0.000 0.000 0.000 0.000 {method 'pop' of 'dict' objects}
1 0.000 0.000 0.000 0.000 {method 'read' of '_io.BufferedReader' objects}
2 0.000 0.000 0.000 0.000 {method 'rfind' of 'str' objects}
7 0.000 0.000 0.000 0.000 {method 'rpartition' of 'str' objects}
34 0.000 0.000 0.000 0.000 {method 'rstrip' of 'str' objects}スクリプトファイルをプロファイルすることができました。
View Comments