これは、なにをしたくて書いたもの？
Pythonのプログラムを関数の行単位でプロファイリングしてくれるモジュール、line_profilerというものがあるらしいので、
試してみようかなと。
GitHub - rkern/line_profiler: Line-by-line profiling for Python
環境
今回の環境は、こちらです。
$ 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
line_profilerを使ってみる
まずは、line_profilerをインストール。
$ python3 -m venv venv $ . venv/bin/activate $ pip3 install line_profiler
バージョン。
$ pip3 freeze ... line-profiler==2.1.2 ...
こんなサンプルプログラムを用意。
line_profiler_example.py
import time def heavy_loop(): for i in range(5000000): loop10() for i in range(10000): loop10() for i in range(10): time.sleep(0.1) print("executed loop") def loop10(): for i in range(10): pass heavy_loop()
実行すると、3秒近くかかるスクリプトです。
$ time python3 line_profiler_example.py executed loop real 0m2.805s user 0m1.799s sys 0m0.004s
line_profilerを使うには、プロファイリング対象の関数に「@profile」デコレーターを付与します。
@profile def heavy_loop(): for i in range(5000000): loop10() for i in range(10000): loop10() for i in range(10): time.sleep(0.1) print("executed loop")
line_profilerをインストールすると、kernprofというコマンドが使えるようになっています。
$ kernprof -h
Usage: kernprof [-s setupfile] [-o output_file_path] scriptfile [arg] ...
Options:
--version show program's version number and exit
-h, --help show this help message and exit
-l, --line-by-line Use the line-by-line profiler from the line_profiler
module instead of Profile. Implies --builtin.
-b, --builtin Put 'profile' in the builtins. Use 'profile.enable()'
and 'profile.disable()' in your code to turn it on and
off, or '@profile' to decorate a single function, or
'with profile:' to profile a single section of code.
-o OUTFILE, --outfile=OUTFILE
Save stats to <outfile>
-s SETUP, --setup=SETUP
Code to execute before the code to profile
-v, --view View the results of the profile in addition to saving
it.
この「kernprof」コマンドの「-l」オプションを指定して、プログラムを実行します。「-l」は、@profileデコレータを付けた関数に
対して、行単位のプロファイリングを有効にするオプションです。
$ kernprof -l line_profiler_example.py executed loop Wrote profile results to line_profiler_example.py.lprof
ちなみに、実行時間は17秒ほどになりました…。
$ time kernprof -l line_profiler_example.py executed loop Wrote profile results to line_profiler_example.py.lprof real 0m17.048s user 0m16.018s sys 0m0.029s
結果は、実行ディレクトリに「スクリプト名.lprof」というファイルができているので、こちらをline_profilerモジュールで見ると
プロファイリング結果として確認することができます。
$ python3 -m line_profiler line_profiler_example.py.lprof
Timer unit: 1e-06 s
Total time: 13.1252 s
File: line_profiler_example.py
Function: heavy_loop at line 3
Line # Hits Time Per Hit % Time Line Contents
==============================================================
3 @profile
4 def heavy_loop():
5 5000001 1557939.0 0.3 11.9 for i in range(5000000):
6 5000000 10541423.0 2.1 80.3 loop10()
7
8 10001 3093.0 0.3 0.0 for i in range(10000):
9 10000 20840.0 2.1 0.2 loop10()
10
11 11 54.0 4.9 0.0 for i in range(10):
12 10 1001838.0 100183.8 7.6 time.sleep(0.1)
13
14 1 59.0 59.0 0.0 print("executed loop")
読み方は、以下です。
- Line … ファイルの行番号
- Hits … 対象の行の実行回数
- Time … 実行に費やされた合計時間。単位は、結果に一緒に表示されている「Timer unit」を確認してください
- Per Hit … 1回の実行の平均時間
- % Time … プロファイリングの合計時間に対する、対象の行の実行時間の割合
- Line Contents … 実際のソースコード。プロファイリングの結果から表示しているわけではなく、現在置かれているソースコードから読み出して表示しています
「% Time」を最初に見て、実行に時間がかかっている割合の大きいところを目安に見ていくとよさそうですね。
ちなみに「-v」オプションを付けると、いきなり結果を表示します（lprofファイルは作成されます）。
$ kernprof -l -v line_profiler_example.py
executed loop
Wrote profile results to line_profiler_example.py.lprof
Timer unit: 1e-06 s
Total time: 13.1355 s
File: line_profiler_example.py
Function: heavy_loop at line 3
Line # Hits Time Per Hit % Time Line Contents
==============================================================
3 @profile
4 def heavy_loop():
5 5000001 1533587.0 0.3 11.7 for i in range(5000000):
6 5000000 10576503.0 2.1 80.5 loop10()
7
8 10001 3032.0 0.3 0.0 for i in range(10000):
9 10000 20567.0 2.1 0.2 loop10()
10
11 11 53.0 4.8 0.0 for i in range(10):
12 10 1001730.0 100173.0 7.6 time.sleep(0.1)
13
14 1 48.0 48.0 0.0 print("executed loop")
