Flask 性能分析与SQL慢查询发现机制

Flask 性能分析

使用werkzeug.middleware.profiler.ProfilerMiddleware中间件对Flask的每个请求进行性能分析。其使用python默认的cProfile或profile对请求入口函数wsgi_app进行性能度量从而达到分析一个请求中各部分性能的目的。wezkzeug是实现Flask的底层包之一。

from werkzeug.middleware.profiler import ProfilerMiddleware

app.wsgi_app = ProfilerMiddleware(app.wsgi_app)

输出的形式如下

PATH: '/xxx/yyy/1'
         45309 function calls (44223 primitive calls) in 0.085 seconds

   Ordered by: internal time, call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      593    0.017    0.000    0.017    0.000 {built-in method io.open}
       18    0.016    0.001    0.016    0.001 {method 'recv_into' of '_socket.socket' objects}
      675    0.007    0.000    0.007    0.000 {built-in method posix.stat}

• ncalls: 调用次数
• tottime: 在指定函数中消耗的总时间（不包括调用子函数的时间）
• percall: 是 tottime 除以 ncalls 的商
• cumtime: 指定的函数及其所有子函数（从调用到退出）消耗的累积时间。这个数字对于递归函数来说是准确的。
• percall: 是 cumtime 除以原始调用（次数）的商（即：函数运行一次的平均时间）
• filename:lineno(function): 提供相应数据的每个函数

如果ncall有两个数字（例如3/1），则表示函数递归。第二个值是原始调用次数，第一个是调用的总次数。请注意，当函数不递归时，这两个值是相同的，并且只打印单个数字。

ProfilerMiddleware参数

class werkzeug.middleware.profiler.ProfilerMiddleware(app, stream=<_io.TextIOWrapper name=’’ mode=‘w’ encoding=‘UTF-8’>, sort_by=(‘time’, ‘calls’), restrictions=(), profile_dir=None, filename_format=’{method}.{path}.{elapsed:.0f}ms.{time:.0f}.prof’)

• app：WSGI应用
• stream：写入统计信息到指定stream中，指定None关闭写入
• sort_by：tuple类型。指定如何对统计信息进行排序。 详见 pstats.Stats.sort_stats()。
• restriction：tuple类型。限制输出结果。详见 pstats.Stats.print_stats()。
• profile_dir：指定一个目录。保存性能度量数据文件（.prof）到此目录。
• filename_format：度量数据文件命名格式。可以指定一个字符串，也可以指定一个可调用类型返回。
  • {method} - 请求方式; GET, POST, etc.
  • {path} - 请求路径.
  • {elapsed} - The elapsed time of the request.
  • {time} - 请求时间

生成调用树

安装依赖

pip install gprof2dot    # 将.prof文件存储的数据转换为dot语言
brew install graphviz    # 根据dot语言的描述绘图

生成调用树

python -m gprof2dot -f pstat your_prof_file.prof | dot -Tsvg -o profile.svg

生成调用树样式的含义：

• 结点信息

+------------------------------+
|        function name         |
| total time % ( self time % ) |
|         total calls          |
+------------------------------+

• 边信息

           total time %
              calls
parent --------------------> children

一种基于Flask-sqlalchemy的SQL慢查询发现机制

使用flask_sqlalchemy.get_debug_queries()，其记录了在一个请求中的所有sql的相关信息。所以我们可以通过其来达成如发生慢查询邮件通知等能力。

from flask_sqlalchemy import get_debug_queries

# sql性能测试
app.config['SQLALCHEMY_RECORD_QUERIES'] = True
SLOW_SQL_BENCHMARK_IN_MS = 0

@app.after_request
def print_slow_sql(response):
    assert SLOW_SQL_BENCHMARK_IN_MS >= 0, \
        "SLOW_SQL_BENCHMARK_IN_MS 必须大于等于0"
    for query in get_debug_queries():
        if query.duration * 1000 > SLOW_SQL_BENCHMARK_IN_MS:
            # app默认警告
            app.logger.warning(
                f"SLOW QUERY: Duration: {query.duration * 1000 :.4f}ms; "
                f"{query.statement}; Parameters: {query.parameters}; "
                f"Context: {query.context}"
            )
    return response

使用cprofile的坑

报错：AttributeError: module ‘profile’ has no attribute ‘run’

解决方案：查看是否有名称为profile的包或文件，删除它就可以解决了。

参考

werkzeug性能度量官方文档

Python3.7 Profilers

gprof2dot性能分析图绘制包

图形化工具graphviz