うどんコード

スパゲッティからうどんへ

Raging Stream

Pythonコードの性能解析

by ·

性能解析は高速化が必要となったさいに必ず必要となる作業です。今回はPythonコードの性能解析方法についてまとめてみました

コンテンツ 非表示
1 Profile
2 cProfile
3 time.perf_counter()

テストコード。適当な性能解析のコードとして、複数の異なる文字列連結方法による性能を解析してみました

  • str_concat1 … s += 'a'による文字列連結
  • str_concat2 … s = ''.join(list)による連結
  • str_concat3 … 2と同様だけど、リストの作成方法を内包表記に
  • str_concat4 … io.StringIOによる連結
import io
import string


def str_concat1(n):
    s = ''
    l = len(string.ascii_lowercase)
    for i in range(n):
        s += string.ascii_lowercase[i % l]


def str_concat2(n):
    sl = []
    l = len(string.ascii_lowercase)
    for i in range(n):
        sl.append(string.ascii_lowercase[i % l])
    s = ''.join(sl)


def str_concat3(n):
    sl = []
    l = len(string.ascii_lowercase)
    s = ''.join([string.ascii_lowercase[i % l]
                 for i in range(n)])


def str_concat4(n):
    sio = io.StringIO()
    l = len(string.ascii_lowercase)
    for i in range(n):
        sio.write(string.ascii_lowercase[i % l])
    s = sio.getvalue()


def main():
    loop_num = 1000000
    s = str_concat1(loop_num)

    assert(s == str_concat2(loop_num))
    assert(s == str_concat3(loop_num))
    assert(s == str_concat4(loop_num))


if __name__ == "__main__":
    main()

上記コードは各方法とも100万回ずつ文字を連結していますが通常の実行時間は0.932秒です

% time python  python/profile_usage.py
python python/profile_usage.py  0.00s user 0.01s system 1% cpu 0.932 total

Profile

もっとも簡単なのはprofileモジュールを使用する方法だと思います。コマンドラインで指定するだけでプログラム全体の詳細なプロファイルが得られます

% python -m profile -s cumtime python/profile_usage.py
         2001791 function calls (2001730 primitive calls) in 10.562 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   10.562   10.562 profile:0(<code object <module> at 0x000000000304c710, file "python/profile_usage.py", line 1>)
      2/1    0.000    0.000   10.562   10.562 :0(exec)
        1    0.000    0.000   10.562   10.562 profile_usage.py:1(<module>)
        1    0.016    0.016   10.547   10.547 profile_usage.py:35(main)
        1    3.422    3.422    5.641    5.641 profile_usage.py:27(str_concat4)
        1    2.266    2.266    4.328    4.328 profile_usage.py:12(str_concat2)
  1000000    2.203    0.000    2.203    0.000 :0(write)
  1000142    2.062    0.000    2.062    0.000 :0(append)
        1    0.000    0.000    0.297    0.297 profile_usage.py:20(str_concat3)
        1    0.281    0.281    0.281    0.281 profile_usage.py:23(<listcomp>)
        1    0.266    0.266    0.266    0.266 profile_usage.py:5(str_concat1)
.
.
.

結果を見るとstr_concat4()が最も遅く5.641秒、str_concat1()が最も高速で0.281秒となっています。

-sオプションで表示方法を指定できcumtimeは子関数含めた累積時間、tottimeはトータル時間、callsは呼び出し回数でソートされて出力されます。(他のオプション)

profileモジュールは最もお手軽ですが、欠点は実行時間でしょうか。上記の場合、10.562秒と、もともとの処理時間に対して10倍以上の時間がかかっています

cProfile

cProfileはProfileのC実装版で高速に動作することで、性能への影響が小さいのが特徴です。使い方もProfileと変わらないので、通常はこちらを使用するといいと思います

% python -m cProfile -s cumtime python/profile_usage.py
          2001790 function calls (2001729 primitive calls) in 1.161 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      2/1    0.000    0.000    1.161    1.161 {built-in method builtins.exec}
        1    0.000    0.000    1.161    1.161 profile_usage.py:1(<module>)
        1    0.002    0.002    1.155    1.155 profile_usage.py:35(main)
        1    0.246    0.246    0.385    0.385 profile_usage.py:12(str_concat2)
        1    0.233    0.233    0.345    0.345 profile_usage.py:27(str_concat4)
        1    0.272    0.272    0.272    0.272 profile_usage.py:5(str_concat1)
        1    0.002    0.002    0.151    0.151 profile_usage.py:20(str_concat3)
        1    0.143    0.143    0.143    0.143 profile_usage.py:23(<listcomp>)
  1000142    0.133    0.000    0.133    0.000 {method 'append' of 'list' objects}
  1000000    0.111    0.000    0.111    0.000 {method 'write' of '_io.StringIO' objects}

cProfileでは実行時間が1.162秒と30%程度の増加に抑えられています。Profileの10倍と大きな違いがありますね。

また面白ことに相対的な結果も若干異なっています。Profileではconcat4 > concat2 > concat3 > concat1の順だったのが、cProfileの結果ではconcat2 > concat4 > concat 1 > concat3の順となっています

time.perf_counter()

次はより原始的な方法で、その環境での最も高精細な時間を返してくれるtime.perf_counter()を用いる方法です。計測用のコードを埋め込む必要がありますが、実行時間への影響を最小限に任意の間の時間を計測することが可能です

import time
.
.
.
def main():
    loop_num = 1000000
    t = []
    t.append(time.perf_counter())
    s = str_concat1(loop_num)
    t.append(time.perf_counter())
    assert(s == str_concat2(loop_num))
    t.append(time.perf_counter())
    assert(s == str_concat3(loop_num))
    t.append(time.perf_counter())
    assert(s == str_concat4(loop_num))
    t.append(time.perf_counter())

    for i in range(len(t)-1):
        print(f'str_concat{i+1} ... {t[i+1] - t[i]} sec')

% time python  python/profile_usage.py
str_concat1 ... 0.25689799999999996 sec
str_concat2 ... 0.2015941 sec
str_concat3 ... 0.16176840000000003 sec
str_concat4 ... 0.19579999999999997 sec
python python/profile_usage.py  0.00s user 0.01s system 1% cpu 0.982 total

上記結果では実行時間への影響が5%程度とほぼ誤差の範囲に抑えられています。また面白ことにまたまた結果が変わって今度は concat1 > concat2 > concat4 > concat3になりました。この辺りの理由もおっていくと面白いかもしれません…

タグ:

おすすめ