前回は Flask アプリケーションのテストとコードカバレッジの測定を行いました。今回は Flask アプリケーションの CPU とメモリ使用量のプロファイリングを試してみます。内容としてはライブラリやツールの紹介となっています。
前回と同様に Flask の Tutorial で紹介されている Flaskr と呼ばれる blog application を用いています。
- CPU Profiling
- Memory Profiling
- Flask-DebugToolbar
CPU Profiling
アプリケーションの各処理の速度を測定することで, ボトルネックを特定する手がかりを得ることができます。今回は werkzeug.middleware.profiler を用いて計測, 同時に生成された cProfile を SnakeViz で可視化する方法と, pyinstrument で計測/可視化方法の2つを紹介します。
他にも, ここでは紹介しませんが APM (Application Performance Monitoring) tool としては Retrace (有償) などがあります。
werkzeug.middleware.profiler.ProfilerMiddleware
flaskr/__init__.py 内で werkzeug.middleware.profiler.ProfilerMiddleware を import します。ProfilerMiddleware の設定は以下で profile_dir に指定した場所に cProfile が生成されます。
app.config['PROFILE'] = True
app.wsgi_app = ProfilerMiddleware(app.wsgi_app,
profile_dir=".",
sort_by=['tottime'],
restrictions=[10])
flaskr/__init__.py の全体のコードは以下です。
import os
import sys
from flask import Flask
from werkzeug.middleware.profiler import ProfilerMiddleware
def create_app(test_config=None):
"""Create and configure an instance of the Flask application."""
app = Flask(__name__, instance_relative_config=True)
app.config.from_mapping(
# a default secret that should be overridden by instance config
SECRET_KEY="dev",
# store the database in the instance folder
DATABASE=os.path.join(app.instance_path, "flaskr.mysql"),
)
if test_config is None:
# load the instance config, if it exists, when not testing
app.config.from_pyfile("config.py", silent=True)
else:
# load the test config if passed in
app.config.update(test_config)
# ensure the instance folder exists
try:
os.makedirs(app.instance_path)
except OSError:
pass
@app.route("/hello")
def hello():
return "Hello, World!"
# register the database commands
from flaskr import db
db.init_app(app)
# apply the blueprints to the app
from flaskr import auth, blog
app.register_blueprint(auth.bp)
app.register_blueprint(blog.bp)
# make url_for('index') == url_for('blog.index')
# in another app, you might define a separate main index here with
# app.route, while giving the blog blueprint a url_prefix, but for
# the tutorial the blog will be the main index
app.add_url_rule("/", endpoint="index")
app.config['PROFILE'] = True
app.wsgi_app = ProfilerMiddleware(app.wsgi_app,
profile_dir=".",
sort_by=['tottime'],
restrictions=[10])
return app
flask run コマンドを実行し Web ブラウザから `/` にアクセスすると, 標準出力に以下のメトリクスが出力されます。設定通り, tottime の降順に上位10件が表示されています。
PATH: '/'
34641 function calls (32306 primitive calls) in 0.073 seconds
Ordered by: internal time
List reduced from 832 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.017 0.017 0.017 0.017 {method 'do_handshake' of '_ssl._SSLSocket' objects}
50 0.011 0.000 0.011 0.000 {method 'read' of '_ssl._SSLSocket' objects}
1 0.004 0.004 0.004 0.004 {built-in method _socket.getaddrinfo}
317 0.003 0.000 0.003 0.000 {built-in method __new__ of type object at 0x100a0e568}
2 0.002 0.001 0.002 0.001 {method 'read' of '_io.BufferedReader' objects}
1 0.002 0.002 0.002 0.002 {method 'recv' of '_socket.socket' objects}
1902 0.002 0.000 0.003 0.000 /Users/t2sy/.pyenv/versions/anaconda3-5.3.0/envs/py37/lib/python3.7/site-packages/jinja2/nodes.py:164(iter_child_nodes)
345 0.001 0.000 0.003 0.000 /Users/t2sy/.pyenv/versions/anaconda3-5.3.0/envs/py37/lib/python3.7/site-packages/jinja2/lexer.py:599(tokeniter)
2 0.001 0.001 0.001 0.001 {built-in method builtins.compile}
1040 0.001 0.000 0.001 0.000 {method 'match' of 're.Pattern' objects}
各カラムの意味は以下です。
- ncalls: fucntion call 回数
- tottime: sub-function call を除く fucntion call に消費された時間
- percall: tottime / ncalls
- cumtime: sub-function call を含む fucntion call に消費された時間
- percall: cumtime / ncalls
profile_dir に指定した場所に cProfile ファイル (e.g. GET.root.73ms.1567863700.prof) が生成されます。
SnakeViz
SnakeViz で生成された cProfile を可視化してみます。snakeviz コマンドを実行します。
$ snakeviz GET.root.73ms.1567863700.prof
snakeviz web server started on 127.0.0.1:8080; enter Ctrl-C to exit
上記コマンドを実行後, ブラウザのウィンドウに新しいタブが開かれ, 実行に時間がかかっているところを視覚的に確認できます。
pyinstrument
pyinstrument は call stack profilor です。pyinstrument はProfilerMiddleware + SnakeViz と比較し, 手軽に計測結果を確認できる印象があります。
通常の Python Script では, 以下のように Profiler クラスのインスタンスを作り, start() で測定を開始, stop() で停止します。
from pyinstrument import Profiler
profiler = Profiler()
profiler.start()
# code you want to profile
profiler.stop()
print(profiler.output_text(unicode=True, color=True))Flask アプリケーションではリクエストに対する処理を計測対象にする場合が多いため, デコレータを使ってリクエストの本処理開始前 (flask.Flask.before_request) に Profiler の計測を開始し, 本処理終了後 (flask.Flask.after_request) に停止するようにします。例えば, 以下のように flaskr/__init__.py を変更します。
import os
import sys
from flask import Flask
from pyinstrument import Profiler
from flask import g, make_response, request
def create_app(test_config=None):
"""Create and configure an instance of the Flask application."""
app = Flask(__name__, instance_relative_config=True)
app.config.from_mapping(
# a default secret that should be overridden by instance config
SECRET_KEY="dev",
# store the database in the instance folder
DATABASE=os.path.join(app.instance_path, "flaskr.mysql"),
)
if test_config is None:
# load the instance config, if it exists, when not testing
app.config.from_pyfile("config.py", silent=True)
else:
# load the test config if passed in
app.config.update(test_config)
# ensure the instance folder exists
try:
os.makedirs(app.instance_path)
except OSError:
pass
@app.route("/hello")
def hello():
return "Hello, World!"
# register the database commands
from flaskr import db
db.init_app(app)
# apply the blueprints to the app
from flaskr import auth, blog
app.register_blueprint(auth.bp)
app.register_blueprint(blog.bp)
# make url_for('index') == url_for('blog.index')
# in another app, you might define a separate main index here with
# app.route, while giving the blog blueprint a url_prefix, but for
# the tutorial the blog will be the main index
app.add_url_rule("/", endpoint="index")
@app.before_request
def before_request():
if "profile" in request.args:
g.profiler = Profiler()
g.profiler.start()
@app.after_request
def after_request(response):
if not hasattr(g, "profiler"):
return response
g.profiler.stop()
output_html = g.profiler.output_html()
return make_response(output_html)
return app
flask run コマンドを実行後, Web ブラウザで計測したいページの URL のクエリパラメータに `?profile` を追加してアクセスすることで以下のように計測結果が表示されます。
Memory Profiling
memory_profiler
Web アプリケーションを運用する上で速度だけでなくメモリ使用量を監視することも重要です。memory_profiler で Flask アプリケーションのメモリ使用量をプロファイリングしてみます。memory_profiler では細かいカスタマイズを必要としない場合, 計測対象の関数に profile デコレータを付けることで簡単に計測できます。
ここでは, flaskr/blog.py 内の RDB からブログの投稿を取得する関数のメモリ使用量を調べてみます。
@profile(precision=4)
def get_post(id, check_author=True):
"""Get a post and its author by id.
Checks that the id exists and optionally that the current user is
the author.
:param id: id of post to get
:param check_author: require the current user to be the author
:return: the post with author information
:raise 404: if a post with the given id doesn't exist
:raise 403: if the current user isn't the author
"""
cur = get_db().cursor(buffered=True)
cur.execute(
"SELECT p.id, title, body, created, author_id, username"
" FROM post p JOIN user u ON p.author_id = u.id"
" WHERE p.id = %s",
(id,),)
resp = cur.fetchone()
if resp is None:
abort(404, "Post id {0} doesn't exist.".format(id))
keys = ['id', 'title', 'body', 'created', 'author_id', 'username']
post = {}
for k, v in zip(keys, resp):
post[k] = v
if check_author and post["author_id"] != g.user["id"]:
abort(403)
return post
ブログを更新するためのエンドポイント `/<int:id>/update` へのリクエストは update(id) に対応付けられており, この関数の内部で get_post() が呼ばれます。そのため, このエンドポイントに Web ブラウザからアクセスします。以下のように標準出力に関数の各行単位のメモリ使用量が出力されます。
Line # Mem usage Increment Line Contents
================================================
38 37.1836 MiB 37.1836 MiB @profile(precision=4)
39 def get_post(id, check_author=True):
40 """Get a post and its author by id.
41
42 Checks that the id exists and optionally that the current user is
43 the author.
44
45 :param id: id of post to get
46 :param check_author: require the current user to be the author
47 :return: the post with author information
48 :raise 404: if a post with the given id doesn't exist
49 :raise 403: if the current user isn't the author
50 """
51 37.1836 MiB 0.0000 MiB cur = get_db().cursor(buffered=True)
52 37.1836 MiB 0.0000 MiB cur.execute(
53 37.1836 MiB 0.0000 MiB "SELECT p.id, title, body, created, author_id, username"
54 " FROM post p JOIN user u ON p.author_id = u.id"
55 " WHERE p.id = %s",
56 37.1875 MiB 0.0039 MiB (id,),)
57 37.1875 MiB 0.0000 MiB resp = cur.fetchone()
58
59
60 37.1875 MiB 0.0000 MiB if resp is None:
61 abort(404, "Post id {0} doesn't exist.".format(id))
62
63 37.1875 MiB 0.0000 MiB keys = ['id', 'title', 'body', 'created', 'author_id', 'username']
64 37.1875 MiB 0.0000 MiB post = {}
65 37.1875 MiB 0.0000 MiB for k, v in zip(keys, resp):
66 37.1875 MiB 0.0000 MiB post[k] = v
67
68 37.1875 MiB 0.0000 MiB if check_author and post["author_id"] != g.user["id"]:
69 abort(403)
70
71 37.1875 MiB 0.0000 MiB return post, []
Filename: /Users/t2sy/python/flask-testing-profiling/flask/examples/tutorial/flaskr/blog.py
Line # Mem usage Increment Line Contents
================================================
103 37.1836 MiB 37.1836 MiB @bp.route("//update", methods=("GET", "POST"))
104 @login_required
105 @profile(precision=4)
106 def update(id):
107 """Update a post if the current user is the author."""
108 37.2031 MiB 0.0195 MiB post = get_post(id)
109
110 37.2031 MiB 0.0000 MiB if request.method == "POST":
111 title = request.form["title"]
112 body = request.form["body"]
113 error = None
114
115 if not title:
116 error = "Title is required."
117
118 if error is not None:
119 flash(error)
120 else:
121 cnx = get_db()
122 cur = cnx.cursor(buffered=True)
123 cur.execute(
124 "UPDATE post SET title = %s, body = %s WHERE id = %s", (title, body, id)
125 )
126 cnx.commit()
127 return redirect(url_for("blog.index"))
128
129 37.5508 MiB 0.3477 MiB return render_template("blog/update.html", post=post)
ここで, get_post() 内で長さ 1,000,000 のサイズの list を確保するコード (nums = [x**2 for x in range(1000000)]) を追加して再度 `/<int:id>/update` にアクセスしてみます。
Line # Mem usage Increment Line Contents
================================================
38 37.2266 MiB 37.2266 MiB @profile(precision=4)
39 def get_post(id, check_author=True):
40 """Get a post and its author by id.
41
42 Checks that the id exists and optionally that the current user is
43 the author.
44
45 :param id: id of post to get
46 :param check_author: require the current user to be the author
47 :return: the post with author information
48 :raise 404: if a post with the given id doesn't exist
49 :raise 403: if the current user isn't the author
50 """
51 37.2266 MiB 0.0000 MiB cur = get_db().cursor(buffered=True)
52 37.2266 MiB 0.0000 MiB cur.execute(
53 37.2266 MiB 0.0000 MiB "SELECT p.id, title, body, created, author_id, username"
54 " FROM post p JOIN user u ON p.author_id = u.id"
55 " WHERE p.id = %s",
56 37.2305 MiB 0.0039 MiB (id,),)
57 37.2305 MiB 0.0000 MiB resp = cur.fetchone()
58
59 68.3359 MiB 0.0742 MiB nums = [x**2 for x in range(1000000)]
60
61 68.0859 MiB 0.0000 MiB if resp is None:
62 abort(404, "Post id {0} doesn't exist.".format(id))
63
64 68.0859 MiB 0.0000 MiB keys = ['id', 'title', 'body', 'created', 'author_id', 'username']
65 68.0859 MiB 0.0000 MiB post = {}
66 68.0859 MiB 0.0000 MiB for k, v in zip(keys, resp):
67 68.0859 MiB 0.0000 MiB post[k] = v
68
69 68.0859 MiB 0.0000 MiB if check_author and post["author_id"] != g.user["id"]:
70 abort(403)
71
72 68.0859 MiB 0.0000 MiB return post, nums
Filename: /Users/t2sy/python/flask-testing-profiling/flask/examples/tutorial/flaskr/blog.py
Line # Mem usage Increment Line Contents
================================================
103 37.2227 MiB 37.2227 MiB @bp.route("//update", methods=("GET", "POST"))
104 @login_required
105 @profile(precision=4)
106 def update(id):
107 """Update a post if the current user is the author."""
108 68.1016 MiB 30.8789 MiB post, nums = get_post(id)
109
110 68.1016 MiB 0.0000 MiB if request.method == "POST":
111 title = request.form["title"]
112 body = request.form["body"]
113 error = None
114
115 if not title:
116 error = "Title is required."
117
118 if error is not None:
119 flash(error)
120 else:
121 cnx = get_db()
122 cur = cnx.cursor(buffered=True)
123 cur.execute(
124 "UPDATE post SET title = %s, body = %s WHERE id = %s", (title, body, id)
125 )
126 cnx.commit()
127 return redirect(url_for("blog.index"))
128
129 68.4609 MiB 0.3594 MiB return render_template("blog/update.html", post=post)
list を追加する前と比較し約 30 MiB, メモリ使用量が増加していることが確認できます。
Flask-DebugToolbar
Flask-DebugToolbar はプロファイリングに直接的には関係ありませんが, Flask アプリケーションの開発/デバッグに役立つ Toolbar 機能を提供します。
使い方は簡単で, 例えば tutorial の Flaskr の場合, flaskr/__init__.py に以下のように数行追加します。
import os
import sys
from flask import Flask
from flask_debugtoolbar import DebugToolbarExtension
def create_app(test_config=None):
"""Create and configure an instance of the Flask application."""
app = Flask(__name__, instance_relative_config=True)
# Setting flask app
# ...
toolbar = DebugToolbarExtension(app)
return app
flask run コマンドを実行後, Web ブラウザからアクセスすると以下のように 画面の右側に Toolbar が追加されていることが確認できます。Built-In Panels として Request Vars, Config, Route List などがあります。Profiler は default では disable となっています。
Config panel では以下のように app.config の一覧を確認できます。
おわりに
今回のコードは GitHub (feature/profiling-flaskr branch) に置いています。
[1] module-cProfile[2] Pympler
[3] How to Use Python Profilers: Learn the Basics