PythonのWSGIラインプロファイラを試してみた(wsgi_lineprof)

ひょんなことからISUCONに出ることになったので練習してたら休日が溶けました。ISUCONこわい。

ISUCONはWEBアプリケーションのチューニングコンテストなわけですが、そもそもAPのどこにボトルネックがあるかを見つけないと効果的なチューニングは難しいです。そんな時に使えそうなプロファイラをymyzkさんがwsgi_lineprofとして作成されたということをPyCon2017のLTで発表されていましたので試してみました。

ラインプロファイラ？

ラインプロファイラというのは、WEBアプリに限らずアプリケーション実行時にどの行でどの程度時間を要したかを確認するためのツールです。

大体こんな結果になります。

  Line      Hits         Time  Code
===================================
   219                         @app.route('/')
   220                         def get_index():
   221         1          203      page = int(request.args.get('page', 0))
   222         1          123      cur = db().cursor()
   223         1            1      cur.execute("""
：
   234         1         2603      """.format(page * 50))
   235         1           11      products = cur.fetchall()
   236        51           29      for product in products:
   237        50        22391          comment = get_comments(product['id'])

どの行を何回通ったかがHitsでわかり、その合計時間がTimeでわかります。それらを指標にしてチューニングポイントを探っていくことができます。

wsgi_lineprofのインストール

pipで簡単にできます。

$ pip install wsgi_lineprof

使い方

READMEではbottleをつかった例が紹介されていますので、Flaskでの例を示します。といっても、bottleとそこまでかわりません。

app = Flask(__name__, static_folder=str(static_folder), static_url_path='')
:
@app.route('/')
def get_index():
    page = int(request.args.get('page', 0))
:
from wsgi_lineprof.middleware import LineProfilerMiddleware
app = LineProfilerMiddleware(app)

唯一注意するところとしては、app経由のルーティング等、デコレータの呼び出しが終わってからコードを追加するということでしょうか。

この例でいうと、@app.route("/")より前にLineProfilerMiddlewareでappをラップしてしまうと起動できません。

AttributeError: 'LineProfilerMiddleware' object has no attribute 'route'

エラー見れば当たり前なんですが、LineProfilerMiddlewareはもともとのFlaskを継承しているわけではないので、ちゃんとアプリケーションを初期化してから呼び出さないといけないって話です。

もう少し実践的な使い方

app = LineProfilerMiddleware(app)でプロファイルは有効になりますが、このままだと以下の点で少し使いづらいです。

• 出力先が標準出力である
• すべてのソースファイルに対して結果が出力される
• チューニングポイントではないほど短い処理も出力され、本来の問題箇所を見失う

wsgi_lineprofはこのあたりも考慮されており、フィルタを使うと解決できます。これらの問題点に対する解決策としては以下のソースになります。

from wsgi_lineprof.filters import FilenameFilter, TotalTimeSorter
# withで書くべきですが… プロファイル結果の出力用ファイル
f=open("profile.log", "a")
filters = [
    FilenameFilter("/my/application/src/app.py"),  # プロファイル対象のファイル名指定
    lambda stats: filter(lambda stat: stat.total_time > 0.01, stats), # 0.01未満の結果を表示しない
]
# stremで出力ファイルを指定、filtersでフィルタを追加
app = LineProfilerMiddleware(app, stream=f, filters=filters)

基本的には、エントリポイントになるapp.pyだけに絞ってプロファイルを始めるのがいいと思います。

パフォーマンスへの影響

環境にもよりますし、今回は実ファイルへの書き出しもしているのでそれなりにパフォーマンスへは影響があります。私が実際に試していた際は、TPSがプロファイラを有効にすると1/5程度まで下がりました。

そのため、本番環境等も含め常時有効にすることは決してしない法が良いと思います。

まとめ

wsgi_lineprofの結果は1リクエストごとにでるので、実際は集計しながら使うと効果的だと思いますがアプリケーションのボトルネックは本当に探しやすくなりました。wsgi_lineprofをがしがし使っていきたいと思います。