この記事は CAMPHOR- Advent Calendar 2016 の1日目の記事です.
Python の WSGI ミドルウェアとして使えるラインプロファイラ wsgi_lineprof を作成しました. wsgi_lineprof は Django や Pyramid, Flask, Bottle などの WSGI 互換のアプリケーションやフレームワークと組み合わせて利用できるようになっています.
背景
Web アプリケーションを作成する際に, ボトルネックとなっている部分を発見するために, ラインプロファイラは有用です. Ruby での WSGI に対応する Rack には rack-lineprof というライブラリがあり, Rack の middleware として簡単にラインプロファイラを利用できます. ISUCON の参加記事等を見ていると, Ruby ユーザーはこのライブラリを活用しているようで, 羨ましいなという思いがありました.
Python では line_profiler というラインプロファイラーがありますが, kernprof という専用のコマンドを使って Python スクリプトを実行する必要があり, Web アプリケーションのプロファイリングには決して使いやすいものとは言えませんでした.
概要
wsgi_lineprof は WSGI のミドルウェアとして利用できるラインプロファイラです. Python の多くの Web アプリケーションやフレームワークは WSGI に対応しているため, これを簡単に利用することができます. wsgi_lineprof は Web アプリケーションへのリクエストのたびに, 実行された全ての関数と関数内の各行の実行時間を取得し, その結果を出力します.
サンプルプログラム
この記事では, Bottle で実装された以下のようなアプリケーションを利用します. 次のファイルを app.py として保存します:
import time
import bottle
app = bottle.default_app()
def get_title():
# DB アクセス等の代わりに1秒待つ
time.sleep(1)
return "Monty Python"
def fact(n):
if n < 2:
return 1
return n * fact(n - 1)
@app.route('/')
def index():
title = get_title()
number = 500
return "Title: {}\n{}! = {}".format(title, number, fact(number))
if __name__ == "__main__":
bottle.run(app=app)python app.py としてこのプログラムを実行し, http://localhost:8080 にアクセスすると次のようなレスポンスが返ってきます.
Title: Monty Python
500! = 1220136825991110068701238785423046926253574342803192842192413588385845373153881997605496447 (省略)wsgi_lineprof の使い方
wsgi_lineprof は pip で簡単にインストールできます: pip install wsgi_lineprof インストール時に Cython による拡張または C による拡張をコンパイルするので, GCC 等のコンパイラが入っている必要があります. (今後 wheel 等での配布を充実させていく予定です.)
先ほどの app.py の app に wsgi_lineprof をミドルウェアとして追加します:
from wsgi_lineprof.middleware import LineProfilerMiddleware
(中略)
if __name__ == "__main__":
app = LineProfilerMiddleware(app)
bottle.run(app=app)再び python app.py としてこのプログラムを実行し, http://localhost:8080 にアクセスします. すると, 標準出力に以下のようなプロファイリングの結果が出力されます:
Bottle v0.12.10 server starting up (using WSGIRefServer())...
Listening on http://127.0.0.1:8080/
Hit Ctrl-C to quit.
Time unit: 1e-06 [sec]
File: /Users/yusuke/.virtualenvs/wsgi-lineprof/lib/python3.5/site-packages/bottle.py
Name: __init__
Total time: 5e-06 [sec]
Line Hits Time Code
===================================
1929 def __init__(self, *a, **ka):
1930 1 4 self.dict = {}
1931 1 1 if a or ka: self.update(*a, **ka)
File: /Users/yusuke/.virtualenvs/wsgi-lineprof/lib/python3.5/site-packages/bottle.py
Name: fset
Total time: 5e-06 [sec]
Line Hits Time Code
===================================
1656 6 5 def fset(self, value): ls.var = value
File: ./app.py
Name: fact
Total time: 0.001151 [sec]
Line Hits Time Code
===================================
16 def fact(n):
17 500 306 if n < 2:
18 1 0 return 1
19 499 845 return n * fact(n - 1)
(以下省略)プロファイリングの結果は各メソッド・関数ごとに表示されます. まず, 先頭の行からこのプロファイル結果の時間の単位は1μs (マイクロ秒) であることがわかります.
Time unit: 1e-06 [sec]以降は各関数ごとの結果です. 次の結果からは, app.py の fact 関数のプロファイル結果が得られます. 関数全体の実行時間は 0.001151 秒で, それぞれの行が実行された回数と, かかった総時間 (例: 17 行目は500回実行され, 500回の実行にかかった時間は306μs) が分かります.
File: ./app.py
Name: fact
Total time: 0.001151 [sec]
Line Hits Time Code
===================================
16 def fact(n):
17 500 306 if n < 2:
18 1 0 return 1
19 499 845 return n * fact(n - 1)このリクエストを処理する間に利用した全てのメソッドの結果が表示されるため, フレームワーク等を利用している場合は結果が膨大になります. 結果を見やすくするために, ファイル名で表示する範囲を指定したり, 実行時間の遅い順にソートすることができます.
フィルター
wsgi_lineprof ではフィルターと呼ばれる機能を用いて, プロファイル結果を整理することができます. wsgi_lineprof.filters.FilenameFilter は特定のファイル名のもののみの絞り込み, wsgi_lineprof.filters.TotalTimeSorter では total time の長い順にソートすることができます. フィルターはミドルウェアを設定する際に一緒に設定します:
from wsgi_lineprof.filters import FilenameFilter, TotalTimeSorter
(中略)
if __name__ == "__main__":
filters = [
FilenameFilter("app.py"),
TotalTimeSorter()
]
app = LineProfilerMiddleware(app, filters=filters)
bottle.run(app=app)このプログラムを実行すると, 次のような結果が得られます:
Bottle v0.12.10 server starting up (using WSGIRefServer())...
Listening on http://127.0.0.1:8080/
Hit Ctrl-C to quit.
Time unit: 1e-06 [sec]
File: ./app.py
Name: index
Total time: 1.00402 [sec]
Line Hits Time Code
===================================
18 @app.route('/')
19 def index():
20 1 1001447 title = get_title()
21 1 1 number = 500
22 1 2576 return "Title: {}\n{}! = {}".format(title, number, fact(number))
File: ./app.py
Name: get_title
Total time: 1.00141 [sec]
Line Hits Time Code
===================================
8 def get_title():
9 # DB アクセス等の代わりに1秒待つ
10 1 1001409 time.sleep(1)
11 1 4 return "Monty Python"
File: ./app.py
Name: fact
Total time: 0.001369 [sec]
Line Hits Time Code
===================================
13 def fact(n):
14 500 337 if n < 2:
15 1 1 return 1
16 499 1031 return n * fact(n - 1)
127.0.0.1 - - [30/Nov/2016 22:08:20] "GET / HTTP/1.1" 200 1162フィルターを使うことでライブラリ内部の処理時間は表示せずに, 目的のファイルだけのプロファイル結果を表示することが出来ました!
いくつかの組み込みのフィルターが wsgi_lineprof.filters に定義されている他に, ラムダ式 (Iterable[wsgi_lineprof.stat.LineProfilerStat] をとって Iterable[wsgi_lineprof.stat.LineProfilerStat] を返すもの) を用いて簡単にユーザー定義のフィルターを利用できます. 例えば total time が 0.001 秒以上の結果のみを表示するには, 次のようにします:
if __name__ == "__main__":
filters = [
lambda stats: filter(lambda stat: stat.total_time > 0.001, stats),
]
app = LineProfilerMiddleware(app, filters=filters)
bottle.run(app=app)ファイルへの出力
プロファイル結果をファイルに出力したい場合は stream 引数を利用します. 次の例では lineprof.log にプロファイル結果を出力します.
if __name__ == "__main__":
with open("lineprof.log", "w") as f:
app = LineProfilerMiddleware(app, stream=f)
bottle.run(app=app)その他
wsgi_lineprof で実行時間を取得する部分は line_profiler を参考に Cython で実装しています. 具体的には, C API の PyEval_SetTrace を通じてデータを取得しています.
また wsgi_lineprof では, 型ヒントを積極的に記述するようにしています. PyCharm や mypy などで, 静的型検査のメリットを享受できるはずです.
まとめ
この記事では WSGI ミドルウェアとして利用できる新しいラインプロファイラ wsgi_lineprof について紹介しました. このプロファイラが Web アプリケーション・フレームワークの開発や ISUCON 等のコンテストに少しでも役立てば幸いです.
wsgi_lineprof は今後も少しずつ改善していく予定です. バグ修正や改善等の PR は GitHub で受け付けています. リポジトリへの star もお待ちしてます!
CAMPHOR- Advent Calendar 2016 2日目の担当は @ytmatsuge です. お楽しみに!!