Flaskの表示ページのプロファイラをとってみた

2016.04.15

サーモン大好き横山です。

本日はFlaskを使ったページのプロファイラの取り方の一例を紹介したいと思います。

はじめに

Flaskのインストール、デプロイ方法等は以下が参考になります。

準備

今回はApacheを通さずにローカルアプリとして動かして行きます。

環境

virtualenvの環境に、Python2.7系、Flaskをインストールしていきます。

$ virtualenv -p /usr/bin/python2.7 venv
$ . venv/bin/activate
(venv)$ pip install -U pip
(venv)$ pip install flask

コード

Flask のサンプルコード+αで準備します。 今回は、Flaskの依存パッケージの Werkzeug の中にある、 WSGI Application Profiler を紹介します。 細かい事は抜きに実行結果をまず見てもらおうと思います。

app.py

#!/usr/bin/env python
# coding: utf-8

from __future__ import print_function, unicode_literals

from flask import Flask
app = Flask(__name__)

# 追加部分
from werkzeug.contrib.profiler import ProfilerMiddleware
app.config['PROFILE'] = True
app.wsgi_app = ProfilerMiddleware(app.wsgi_app)

@app.route("/")
def hello():
    return "Hello World!"

if __name__ == "__main__":
    app.run()

実行

python app.py で実行した後、別のターミナルから curl 127.0.0.1:5000でアクセスされた結果です。

(venv)$ python app.py
 * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
--------------------------------------------------------------------------------
PATH: '/'
         308 function calls in 0.001 seconds

   Ordered by: internal time, call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       10    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/local.py:68(__getattr__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1243(bind_to_environ)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:756(__init__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1425(match)
       10    0.000    0.000    0.000    0.000 {method 'decode' of 'str' objects}
        6    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/local.py:160(top)

--- skip (120 lines) ----

        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/sessions.py:189(is_null_session)
        1    0.000    0.000    0.000    0.000 {sys.exc_info}
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:60(_warn_if_string)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        2    0.000    0.000    0.000    0.000 {method 'upper' of 'str' objects}
        2    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:867(_get_status_code)
        2    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'itervalues' of 'dict' objects}
        1    0.000    0.000    0.000    0.000 {method 'endswith' of 'unicode' objects}
        1    0.000    0.000    0.000    0.000 {method 'replace' of 'str' objects}
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wsgi.py:699(__iter__)
        1    0.000    0.000    0.000    0.000 app.py:14(hello)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:880(_get_status)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/app.py:1522(should_ignore_error)
        1    0.000    0.000    0.000    0.000 {method 'startswith' of 'str' objects}


--------------------------------------------------------------------------------

 127.0.0.1 - - [14/Apr/2016 14:43:17] "GET / HTTP/1.1" 200 -

Hello World を表示するまでのプロファイルをずらーと表示してくれます。
各項目の説明は以下のようになります。

項目 説明
ncalls 呼び出し回数
tottime この関数が消費した時間の合計 (下位の関数呼び出しの時間は除く)
percall tottime を ncalls で割った値
cumtime 下位の関数を含むこの関数の (実行開始から終了までの) 消費時間の合計
percall cumtime をプリミティブな呼び出し回数で割った値
filename:lineno(function) その関数のファイル名、行番号、関数名

でも、情報が多すぎますね。そこで情報絞ります。

うち自身場合は、tottimeが長い順で20個絞り込んで欲しいので以下の様に書き換えます。

before

app.py

# 追加部分
from werkzeug.contrib.profiler import ProfilerMiddleware
app.config['PROFILE'] = True
app.wsgi_app = ProfilerMiddleware(app.wsgi_app)

after

app.py

# 追加部分
from werkzeug.contrib.profiler import ProfilerMiddleware
app.config['PROFILE'] = True
app.wsgi_app = ProfilerMiddleware(app.wsgi_app, sort_by=['tottime'], restrictions=[20])

結果

tottimeが長い20メソッドが表示されるようになりました。

(venv)$ python app.py
 * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
--------------------------------------------------------------------------------
PATH: '/'
         308 function calls in 0.001 seconds

   Ordered by: internal time
   List reduced from 141 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       10    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/local.py:68(__getattr__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1243(bind_to_environ)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1425(match)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:756(__init__)
        6    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/local.py:160(top)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/ctx.py:325(pop)
       10    0.000    0.000    0.000    0.000 {method 'decode' of 'str' objects}
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/encodings/__init__.py:71(search_function)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/ctx.py:219(__init__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/ctx.py:291(push)
       35    0.000    0.000    0.000    0.000 {isinstance}
        2    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/datastructures.py:1145(set)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1356(__init__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:912(set_data)
        1    0.000    0.000    0.001    0.001 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/app.py:1787(wsgi_app)
        8    0.000    0.000    0.000    0.000 {getattr}
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:744(match)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/app.py:1463(full_dispatch_request)
        2    0.000    0.000    0.000    0.000 {method 'extend' of 'list' objects}
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:1086(get_wsgi_headers)


--------------------------------------------------------------------------------

127.0.0.1 - - [14/Apr/2016 15:16:15] "GET / HTTP/1.1" 200 -

…が、これじゃ違いがわからないので、 time.sleep(5) を追加します。

before

app.py

@app.route("/")
def hello():
    return "Hello World!"

after

app.py

@app.route("/")
def hello():
    import time; time.sleep(5)
    return "Hello World!"

結果

わかりやすい結果が出ました。 こんな風になんの処理がネックになってるかがわかりやすく見つける事が出来ます。

(venv)$ python app.py
 * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
--------------------------------------------------------------------------------
PATH: '/'
         309 function calls in 5.007 seconds

   Ordered by: internal time
   List reduced from 142 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    5.005    5.005    5.005    5.005 {time.sleep}
        6    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/local.py:160(top)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/app.py:1532(make_response)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:756(__init__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/datastructures.py:1087(__contains__)
       10    0.000    0.000    0.000    0.000 {method 'decode' of 'str' objects}
        1    0.000    0.000    5.006    5.006 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/app.py:1463(full_dispatch_request)
       35    0.000    0.000    0.000    0.000 {isinstance}
       10    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/local.py:68(__getattr__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1243(bind_to_environ)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/ctx.py:325(pop)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:744(match)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/ctx.py:291(push)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/ctx.py:219(__init__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/encodings/__init__.py:71(search_function)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1425(match)
        2    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/datastructures.py:1145(set)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1356(__init__)
        1    0.000    0.000    5.005    5.005 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/app.py:1441(dispatch_request)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/datastructures.py:911(__getitem__)


--------------------------------------------------------------------------------

127.0.0.1 - - [14/Apr/2016 15:28:01] "GET / HTTP/1.1" 200 -

まとめ

ベースが profilecProfile がベースになっているので、そちらを知っているととてもわかり易く、かつ手軽にプロファイリングを取得することが出来ます。

Flaskつかっていて、ページが遅いと感じました方へ参考になれば幸いです。

参考