IPythonでコードの実行時間を測る話
こんばんは．1000chです． 先日友人にCheck iOを紹介したところ，「せっかくプログラミングで問題解くなら，実行時間測らないと面白くないよね〜」と言われました． 確かに言われてみると，今まで実行時間なんて考えず，「とりあえず解けりゃいいや！」くらいの感覚でした． てなわけで，今回はIPythonの機能を活用して，コードの実行速度を測ってみようと思います． （「Pythonによるデータ分析入門」を参考にしています）
実行時間の計測
まずは，普通にPythonのtimeモジュールを使って実行時間を測るコードを書いてみましょう．
#coding:utf-8 import time start = time.time() # 実行時間を測りたい処理を記述する # ここまで elapsed_time = time.time() - start
シンプルです．
実行時間を測りたい処理の前後でtime.time()を呼び現在時刻を取得，そのdiffを返すだけです．
試しに使ってみるとこんな感じです．
#coding:utf-8 import time start = time.time() # 任意の処理 for i in range(100000): i ** 2 # ここまで elapsed_time = time.time() - start print("elapsed_time:{0}".format(elapsed_time))
実行結果
elapsed_time:0.0175778865814 #10万回のi**2にかかった時間
ちなみに，実はこの実行時間，その時々によって変わります．
#coding:utf-8 # timecount1.py import time for j in range(10): #同じ処理を10回やってみる start = time.time() #任意の処理 for i in range(100000): i ** 2 # ここまで elapsed_time = time.time() - start print("elapsed_time_{0}:{1}".format(j,elapsed_time))
実行結果
elapsed_time_0:0.0194380283356 elapsed_time_1:0.0138731002808 elapsed_time_2:0.0148088932037 elapsed_time_3:0.0143020153046 elapsed_time_4:0.0134570598602 elapsed_time_5:0.0183911323547 elapsed_time_6:0.0149998664856 elapsed_time_7:0.0136020183563 elapsed_time_8:0.0137221813202 elapsed_time_9:0.0153870582581 # その時々で実行時間が違う
まぁコレでも，だいたいの目安を測るくらいには使えそうですね．
しかしこのような書き方では，全体の実行時間しか知ることができません．
コードの一部分の実行時間を測りたい時や，ボトルネックを探す時には，その前後の時間を取得，diffを計算する必要があるため，結構面倒な感じがします．
いちいちimport timeやらtime.time()を書いてるとコードの可読性が下がってしまい美しくないですね．
IPythonで実行時間を測る
IPythonでは，上記を解決するためのマジックコマンドが用意されています． マジックコマンドとは，IPythonのインタラクティブシェル上でのみ利用できるコマンドで，通常のPythonには無い機能を利用できます． イメージ的には，いわゆるコマンドラインプログラムのようなモノと思えば良いようです． 実際，各種コマンドはそれぞれが「コマンドラインオプション」を持っていたりするようです．
ではまず，コード片の実行速度を測ってみましょう．
%timeと%timeit
コード片の実行時間計測には，IPythonにおけるマジックコマンド$timeか%timeitを利用します．これらのコマンドは，実行時間を計測したい処理の前に記述することで，その処理の実行時間を計測・表示してくれます．
こんな感じ．
# ipython3 インタラクティブシェル In [1]: %time a = 10 CPU times: user 3 µs, sys: 0 ns, total: 3 µs Wall time: 5.96 µs In [2]: %time l = range(10000) CPU times: user 4 µs, sys: 1e+03 ns, total: 5 µs Wall time: 7.87 µs In [4]: %time l2 = [x ** 2 for x in l] CPU times: user 5.61 ms, sys: 327 µs, total: 5.94 ms Wall time: 7.13 ms In [5]: %time for i in l2: File "<unknown>", line 1 for i in l2: ^ SyntaxError: unexpected EOF while parsing # for文はダメっぽい？ In [6]: %time l3 = [x + 1 for x in l] CPU times: user 791 µs, sys: 196 µs, total: 987 µs Wall time: 993 µs
大切なのはWall timeという方で，これがコード片の実行時間部分になります． きちんと単位までつけて表示してくれているのはありがたい所です． CPU timesはよくわかんないですw
ただ，for文に関してはうまく時間計測できないようです...使い方が悪いのかなぁ． 行単位でコード片の実行時間を計測するだけなんでしょうか．
ともあれこのように%timeコマンドでコードの実行時間を測ることができます．
しかし，先ほど見たようにコードの実行時間はその時々により変動します．
In [1]: %time l = [x ** 2 for x in range(100000)] CPU times: user 50.1 ms, sys: 3.42 ms, total: 53.5 ms Wall time: 52.5 ms In [2]: %time l = [x ** 2 for x in range(100000)] CPU times: user 48.5 ms, sys: 3.04 ms, total: 51.6 ms Wall time: 51 ms In [3]: %time l = [x ** 2 for x in range(100000)] CPU times: user 48 ms, sys: 2.06 ms, total: 50 ms Wall time: 49.4 ms In [4]: %time l = [x ** 2 for x in range(100000)] CPU times: user 44.6 ms, sys: 1.69 ms, total: 46.3 ms Wall time: 45.7 ms In [5]: %time l = [x ** 2 for x in range(100000)] CPU times: user 48.5 ms, sys: 1.78 ms, total: 50.3 ms Wall time: 49.6 ms In [6]: %time l = [x ** 2 for x in range(100000)] CPU times: user 45.9 ms, sys: 1.66 ms, total: 47.5 ms Wall time: 46.8 ms In [7]: %time l = [x ** 2 for x in range(100000)] CPU times: user 45.1 ms, sys: 1.74 ms, total: 46.9 ms Wall time: 46.3 ms In [8]: %time l = [x ** 2 for x in range(100000)] CPU times: user 47.2 ms, sys: 1.86 ms, total: 49 ms Wall time: 48.4 ms In [9]: %time l = [x ** 2 for x in range(100000)] CPU times: user 48.7 ms, sys: 1.87 ms, total: 50.6 ms Wall time: 50.1 ms In [10]: %time l = [x ** 2 for x in range(100000)] CPU times: user 53.5 ms, sys: 1.86 ms, total: 55.4 ms Wall time: 55.2 ms
試しに10回やっただけでも，55.2ms ~ 45.7msとなかなかにブレがあることがわかります．
そこでIPythonでは，自動で%timeを適切な回数実行し，その平均値を実行時間の目安として返してくれる%timeitというコマンドも用意されています．
In [11]: %timeit l = [x ** 2 for x in range(100000)] 10 loops, best of 3: 45 ms per loop In [12]: %timeit l = [x ** 2 for x in range(100000)] 10 loops, best of 3: 44.4 ms per loop In [13]: %timeit l = [x ** 2 for x in range(100000)] 10 loops, best of 3: 44.3 ms per loop In [13]: %timeit l = [x ** 2 for x in range(100000)] 10 loops, best of 3: 45.1 ms per loop
何度か試してみても，ブレはなかなか少なそうです． 単純な平均ではなく，ベストタイムの平均なのでしょうか．
%prunと%run -p
細かいコード片の実行時間を計測することができたので，今度はボトルネックの探索をしてみましょう． Pythonのプロファイリングツールとして，cProfileモジュールというものがあり，関数ごとにその実行時間を表示してくれます． 利用は次のような感じ．-sオプションで実行時間のかかる順にソートできます
python -m cProfile -s cumulative <script_name>
てなわけで，とりあえずこんなコードを動かしてみます．
#coding:utf-8 # timecount2.py import math def func1(): ls = [] for i in range(10000): ls.append(i) return ls def func2(): ls = [] for i in range(10000): ls.append(i * i * i) return ls def func3(): ls = [] for i in range(10000): ls.append(pow(i,i)) return ls func1() func2() func3()
実行結果
% python -m cProfile -s cumulative timecount2.py [~/programming/python/blog/code_plofile] 40433 function calls in 7.124 seconds Ordered by: cumulative time ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 7.124 7.124 {built-in method exec} 1 0.015 0.015 7.124 7.124 timecount2.py:2(<module>) 1 0.011 0.011 7.102 7.102 timecount2.py:16(func3) 10000 7.089 0.001 7.089 0.001 {built-in method pow} 30152 0.004 0.000 0.004 0.000 {method 'append' of 'list' objects} 1 0.002 0.002 0.003 0.003 timecount2.py:10(func2) 1 0.002 0.002 0.003 0.003 timecount2.py:4(func1) (以下略)
func3が圧倒的に時間がかかっており，powによる累乗がハイコストであることがわかります．
このcProfileツールをIPythonから使うことができます．
それがマジック関数%prunです．
使い方はこんな感じ．
In [4]: %run timecount2 #先ほどのコードを読み込む In [5]: %prun func1() # func1を測定 10004 function calls in 0.002 seconds Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 1 0.001 0.001 0.002 0.002 timecount2.py:4(func1) 10000 0.001 0.000 0.001 0.000 {method 'append' of 'list' objects} 1 0.000 0.000 0.002 0.002 <string>:1(<module>) 1 0.000 0.000 0.002 0.002 {built-in method exec} 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} In [6]: %prun func2() #func2を測定 10004 function calls in 0.003 seconds Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 1 0.002 0.002 0.003 0.003 timecount2.py:10(func2) 10000 0.001 0.000 0.001 0.000 {method 'append' of 'list' objects} 1 0.000 0.000 0.003 0.003 <string>:1(<module>) 1 0.000 0.000 0.003 0.003 {built-in method exec} 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} In [7]: %prun func3() #func3を測定 20004 function calls in 6.934 seconds Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 10000 6.911 0.001 6.911 0.001 {built-in method pow} 1 0.011 0.011 6.934 6.934 <string>:1(<module>) 1 0.010 0.010 6.923 6.923 timecount2.py:16(func3) 10000 0.002 0.000 0.002 0.000 {method 'append' of 'list' objects} 1 0.000 0.000 6.934 6.934 {built-in method exec} 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
いったん%runでスクリプトを読み込み，読み込んだ関数に対し%prunコマンドを用いています．
先ほどと同様，func3で多大な時間がかかっていることがわかります．
なお，%prunでも先ほどのcProfileのようなオプションを与えることができます．
外部に保存したスクリプトファイル自体を直接計測したい場合は，%run -pコマンドを利用するとよいみたいです．
ソート順も指定すると次のような感じ．
In [8]: %run -p -s cumulative timecount2.py 40059 function calls (40058 primitive calls) in 6.992 seconds Ordered by: cumulative time ncalls tottime percall cumtime percall filename:lineno(function) 2/1 0.000 0.000 6.992 6.992 {built-in method exec} 1 0.000 0.000 6.992 6.992 <string>:1(<module>) 1 0.000 0.000 6.992 6.992 interactiveshell.py:2450(safe_execfile) 1 0.000 0.000 6.992 6.992 py3compat.py:97(execfile) 1 0.015 0.015 6.991 6.991 timecount2.py:2(<module>) 1 0.011 0.011 6.972 6.972 timecount2.py:16(func3) 10000 6.959 0.001 6.959 0.001 {built-in method pow} 30007 0.003 0.000 0.003 0.000 {method 'append' of 'list' objects}
こちらは先ほどのpython -m cProfile -s cumulative timecount2.pyと同様の挙動と言えるでしょう．
とまぁこのように，関数単位でどのくらい時間がかかるか，を測定することができました．
-s cumulativeオプションを指定することで関数を実行時間順に並べられるため，ボトルネックの検出に使えそうですね．
まとめ
- IPythonをもちいたコードの実行時間計測を調べた
- コード片測定：%time or %timeit
- ボトルネック検出：%prun or &run -p
ちなみに
line_profilerも導入しようとしたんだけどpython3系未対応っぽい？ 2系には入ったのでそのうちこちらも記事かくかも．
