この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。
サーモン大好き横山です。
本日はFlaskを使ったページのプロファイラの取り方の一例を紹介したいと思います。
はじめに
Flaskのインストール、デプロイ方法等は以下が参考になります。
- virtualenvを使っていろいろなライブラリを手軽にためそう
- EC2上でFlaskを動かしてみる
- Amazon LinuxでFlask/Apache/mod_wsgi/virtualenvなアプリを動かす
準備
今回は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 -
まとめ
ベースが profile
や cProfile
がベースになっているので、そちらを知っているととてもわかり易く、かつ手軽にプロファイリングを取得することが出来ます。
Flaskつかっていて、ページが遅いと感じました方へ参考になれば幸いです。