読者です 読者をやめる 読者になる 読者になる

すこしふしぎ.

VR/HI系院生による技術ブログ.まったりいきましょ.(友人ズとブログリレー中.さぼったら焼肉おごらなきゃいけない)

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系には入ったのでそのうちこちらも記事かくかも.