最適化入門

Python でプロファイラを使ってプログラムの実行時間を計測し、速くする方法について見てみよう。

最適化とは

プログラムの最適化とは

• プログラムのリソース利用効率を改善すること
  • メモリ使用量を減らす
  • 処理時間を減らす
  • ディスク使用量を減らす
• システムのリソースを減らせる
  • →コスト削減してより安くサービス提供できる
• 同じリソースでより多くの処理ができる
  • →よりたくさんの利用者に同時に使ってもらえる

今回は処理時間の短縮に注目する

時間がかかっているとは

プログラムの処理時間を計測してみよう。

5秒かかるプログラムを2つ用意したとして、 time コマンドで計測してみる。

% time ./wait.py
./wait.py  0.02s user 0.02s system 0% cpu 5.057 total
% time ./busy.py
./busy.py  5.01s user 0.02s system 99% cpu 5.038 total

どちらもプログラムを開始してから終了するまでに total 5秒かかっているが、少し様子が違う

• 前者はCPU使用率が低いのに時間がかかっている
• 後者はCPU使用率が高くて時間がかかっている

実際に使ったソースを見てみる:

wait.py

#!/usr/bin/env python

import time

def main():
    time.sleep(5)

if __name__ == '__main__':
    main()

busy.py

#!/usr/bin/env python

import time

def main():
    start = time.time()
    while time.time() - start < 5:
        pass

if __name__ == '__main__':
    main()

時間の使い方が異なっている

• 前者は sleep() を呼んだらあとは抜けてくるのを待つだけ
• 後者はせわしなく時刻を確認し続けている

一般にプログラムは以下のようなことに時間を使っている

• CPUを使って計算をしている
• ディスクの読み書きを待っている
  • データの読み書き
  • プログラムのロード
• 通信の応答を待っている
• 人による入力を待っている
• ...

時間の使い方を改善する

• 計算にかかっている時間を改善する
  • →より計算量の少ないやり方
  • →もっと計算資源を投入
• 待ちにかかっている時間を改善する
  • →より待ちが少なくなるやり方
  • →待ちの間にできることをする

ボトルネックを探す

プログラム中で改善できそうな所はどこか？

• 時間を消費している大きな固まりを探す
  • 時間を消費している所に短縮の可能性
  • 一回でたくさん時間を使っている
  • 何度も実行され、合計で時間を使っている
  • 消費してない所には削れる余地がない
• 2つの時間を意識して対策を考えていく
  • 計算時間を改善するのか
  • 待ち時間を改善するのか

探し方

• プログラムを分割できるなら、それぞれをtimeコマンドで計測
• プログラムを分割して計測することができない場合
  • time コマンドではプログラム全体の時間しか測れない
  • プログラムのどの部分で時間を消費しているか見るには？

ログを入れる

処理の前後の時刻の差をログ出力

start = time.time()
some_func()
print "%f sec" % (time.time() - start)

start = time.clock()
some_func()
print "%f sec" % (time.clock() - start)

• わりとどこでも使える手法
  • プログラミング言語、実行環境によらず使える
  • cf. printf デバッグ
• あちこちにログを埋めて回る必要があるのは大変
  • 2分探索すればある程度は楽をできるけど

cProfile

Python に同梱されている、「プロファイラ」と呼ばれるツールの一つ。

• それぞれの関数の呼び出し統計を取得する
  • 呼び出された回数
  • かかった時間
• 関数の呼び出し、復帰をフックして時間を計測
• 計測処理は C 言語で実装されている (_lsprof.so)

コマンドラインから

time コマンドのように実行するプログラムを引数として与えて実行

% python -m cProfile wait.py
         4 function calls in 5.002 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.001    0.001    5.002    5.002 wait.py:3(<module>)
        1    0.000    0.000    5.001    5.001 wait.py:5(main)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    5.001    5.001    5.001    5.001 {time.sleep}

項目	値の意味
ncalls	呼び出された回数
tottime	消費時間(呼び出したものを含まない)
percall	呼び出し一回あたりの消費時間(tottime/ncalls)
cumtime	消費時間(呼び出したものを含む)
percall	呼び出し一回あたりの消費時間(cumtime/ncalls)

• モジュールがロードされて、main() を呼んで、その中で time.sleep() を呼んでいた
• wait.py の 5 行目で定義された main 関数で 5 秒かかっている
  • tottime が 0 → そこから呼び出した関数で時間を食っている
• time.sleep で 5 秒かかっている → これ

コマンドラインから cProfile.py を実行すると

• プログラム全体を対象にして、簡易にプロファイリングできる
• サービス(デーモン)には適用できない

コードにうめこむ

• プログラム中にプロファイルのためのコードを埋め込む
  • 計測対象の処理の入口だけでよい
  • サービス(デーモン)の一部の処理でもいける
• ファイルに計測結果を出力しておける
  • 標準出力が使えない場合にもいける

wait_profile.py

#!/usr/bin/env python

import cProfile
import time

def main():
    time.sleep(5)

if __name__ == '__main__':
    cProfile.run("main()", "wait.prof")

% python -c "import pstats; pstats.Stats('wait.prof').strip_dirs().sort_stats(-1).print_stats()"
Fri Jun 17 00:25:58 2016    wait.prof

         4 function calls in 5.005 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    5.005    5.005 <string>:1(<module>)
        1    0.000    0.000    5.005    5.005 wait_profile.py:6(main)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    5.005    5.005    5.005    5.005 {time.sleep}

最適化の進めかた

機能要件を維持しつつ、非機能要件を改善していく

• 機能要件
  • 入力に対してどういう出力をするか
• 非機能要件
  • 性能に対する要件
  • メモリ使用量 XX MB 以内とか、実行時間 YY 秒以内とか

すすめかた

• 機能要件のテスト結果をグリーンに保ちながら実装を変更
• プログラムを実行して性能を計測
• くり返す

やってみよう

フィボナッチ数列

fib.py

#!/usr/bin/env python

def fib(n):
    if n == 0:
        return 0
    elif n == 1:
        return 1
    else:
        return fib(n-2) + fib(n-1)

if __name__ == '__main__':
    assert fib(30) == 832040

% time ./fib.py
python fib.py  0.52s user 0.01s system 98% cpu 0.540 total
% python -m cProfile fib.py
         2692539 function calls (3 primitive calls) in 1.084 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.084    1.084 fib.py:3(<module>)
2692537/1    1.084    0.000    1.084    1.084 fib.py:3(fib)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

この例の場合、fib の呼び出し回数が多すぎる。(tottime の M/N は再帰呼び出しM回、再帰でない呼び出しがN回の意味)

time コマンドで計測されたプロファイルなしでの実行時間(0.540s)と、プロファイルありでの実行時間(1.084s)を比べると後者の方が時間かかっていることにも注意

• プロファイルによるオーバーヘッド(関数呼び出し毎に計測のための処理)
• 呼び出し回数の多い関数とそうでないものの比率が、通常動作時とずれる場合があるので注意

機能を維持したまま性能を改善する

• 機能の維持: テストで保証(assert の行)
• 呼び出し回数が多い
  • fib(30) を計算するには fib(29), fib(28), ..., fib(0) がわかっていればよいはず
  • 2692537回も計算してしまっている
  • → 一度計算した結果を覚えておけば速くなる？

実際にやってみる

• 計算結果を貯めるための辞書を用意しておく
• 計算したら辞書に登録してから値を返す
• 計算する前に辞書にあったらそれを返す

fib_optimized.py

#!/usr/bin/env python

cache = {}

def fib(n):
    if n in cache:
        return cache[n]
    if n == 0:
        cache[n] = 0
    elif n == 1:
        cache[n] = 1
    else:
        cache[n] = fib(n-2) + fib(n-1)
    return cache[n]

if __name__ == '__main__':
    assert fib(30) == 832040

% python -m cProfile fib_optimized.py
         61 function calls (3 primitive calls) in 0.000 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 fib_optimized.py:3(<module>)
     59/1    0.000    0.000    0.000    0.000 fib_optimized.py:5(fib)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

呼び出し回数が減って、全体の時間も短縮できている!

例題二つめ。beg から end までの和を取る関数を、標準関数sumを使って実装してある。

takesum.py

#!/usr/bin/env python

def takesum(beg, end):
    "take sum of beg, beg+1, ..., end"
    assert beg <= end
    i = beg
    xs = []
    while i <= end:
        xs.append(i)
        i += 1
    return sum(xs)

if __name__ == '__main__':
    assert takesum(0, 10000000) == 50000005000000

% python -m cProfile takesum.py
         10000005 function calls in 3.482 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.076    0.076    3.482    3.482 takesum.py:3(<module>)
        1    2.418    2.418    3.405    3.405 takesum.py:3(takesum)
 10000001    0.878    0.000    0.878    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.109    0.109    0.109    0.109 {sum}

どうしたら処理時間を短縮できるか考えてみよう。

• 無駄な処理を削れないか
  • リスト構築の必要ある？
• 計算資源をつっこんで速くできないか
  • もっと速いマシンで実行する？
  • 並列処理させる？
• なるべく計算しないで済む方法はないか
  • 足しあげる必要ある？

まとめ

• プログラムの処理にかかる時間: 計算してるか、何かを待っているか
• ボトルネックを見付けて処理時間を短縮する
• 処理の前後の時刻の差をログに出して絞り込む
• プロファイラを使うとボトルネックの検出を素早く確実にできる場合がある
  • 関数呼び出しにフックして消費時間と呼び出し回数を計測してくれる
  • プロファイル結果に呼び出し関係とかを添えて可視化するツールを活用するとよいかも
  • cProfile をクラスのメソッド内で使う場合は: http://qiita.com/yoichi22/items/e4fe74e5b9afa47b0887
• 現実にはそう単純にいかない場合もある(むしろそっちの方が多い)
  • プロファイラのオーバーヘッドが効いてくる場合
  • プロファイラ上では速くなってるのにプロファイラなしで実行すると速くなってない
  • 複数システムをまたぐ処理の場合
  • どのシステムがボトルネックになっているのかわからない
  • 再現性がない場合
  • 実行の度に処理時間の揺れがあり改善しているのかわからない
• 基本的な戦略
  • 再現性を確保する(手順をうまいことやる、再現性のある指標を選ぶ)
  • ボトルネックを絞り込む(部分部分を計測して時間かかっている所を探す)
  • 変更前後のコードで計測(改善してたら採用、駄目なら別の案を考える)