【调优工具】python性能分析工具cProfiler

Python中最常用的性能分析工具主要有：

• cProfiler
  统计在整个代码执行过程中，每个函数调用的次数和消耗的时间

• line_profiler
  分析每一行代码的运行时间，方便定位程序运行效率瓶颈

• memory_profiler
  分析每行代码的内存使用情况，以进行内存消耗分析

接下来使用cProfiler对Python性能进行分析

一、快速使用

官方文档的一个简单例子来对cProfiler的简单使用进行介绍

import cProfile
import re
cProfile.run('re.compile("foo|bar")')

分析结果：

    244 function calls (237 primitive calls) in 0.002 seconds
Ordered by: standard name
ncalls  tottime  percall  cumtime percall filename:lineno(function)
   1    0.000    0.000    0.001   0.001 <string>:1(<module>)
   1    0.000    0.000    0.001   0.001 re.py:232(compile)
   1    0.000    0.000    0.001   0.001 re.py:271(_compile)
   1    0.000    0.000    0.000   0.000 sre_compile.py:249(_compile_charset)
   1    0.000    0.000    0.000   0.000 sre_compile.py:276(_optimize_charset)
   2    0.000    0.000    0.000   0.000 sre_compile.py:453(_get_iscased)
   1    0.000    0.000    0.000   0.000 sre_compile.py:461(_get_literal_prefix)
   1/3    0.000    0.000    0.000   0.000 sre_compile.py:492(_get_charset_prefix)

从分析报告结果中可以得知：

1. 整个过程一共有244个函数调用被监控，其中237个是原生调用(即不涉及递归调用)
2. 总共执行的时间为0.002秒
3. 结果列表中是按照标准名称进行排序，也就是按照字符串的打印方式(数字也当作字符串)
4. 在列表中：
   - ncalls表示函数调用的次数(有两个数值表示有递归调用，总调用次数/原生调用次数)
   - tottime是函数内部调用时间(不包括他自己调用的其他函数的时间)
   - percall等于 tottime/ncalls
   - cumtime累积调用时间，与tottime相反，它包含了自己内部调用函数的时间
   - percall等于 cumtime/ncalls
   - 最后一列，文件名，行号，函数名

二、优雅使用

2.1 常用接口

Python给提供了很多接口方便灵活的进行性能分析，其中主要包含两个类cProfile模块的Profile类和pstat模块的Stats类

可以通过这两个类来将代码分析的功能进行封装以便在项目的其他地方能够灵活重复的使用进行分析

对Profile以及Stats的几个常用接口进行简单总结：

2.1.1 Profile类

• enable(): 开始收集性能分析数据
• disable(): 停止收集性能分析数据
• create_stats(): 停止收集分析数据，并为已收集的数据创建stats对象
• print_stats(): 创建stats对象并打印分析结果
• dump_stats(filename): 把当前性能分析的结果写入文件(二进制格式)
• runcall(func, *args, **kwargs): 收集被调用函数func的性能分析数据

2.1.2 Stats类

pstats模块提供的Stats类可以读取和操作stats文件(二进制格式)

import pstats
p = pstats.Stats('stats.prof')

Stats类可以接受stats文件名，也可以直接接受cProfile.Profile对象作为数据源

• strip_dirs(): 删除报告中所有函数文件名的路径信息
• dump_stats(filename): 把stats中的分析数据写入文件(效果同cProfile.Profile.dump_stats())
• sort_stats(*keys): 对报告列表进行排序，函数会依次按照传入的参数排序，关键词包括calls, cumtime等，具体参数参数
• reverse_order(): 逆反当前的排序
• print_stats(restrictions): 把信息打印到标准输出
  restrictions用于控制打印结果的形式, 例如(10, 1.0, "..py.")表示打印所有py文件的信息的前10行结果

有了上面的接口便可以使用分析器来分析程序执行，例如可以通过写一个带有参数的装饰器，这样想分析项目中任何一个函数，便可方便的使用装饰器来达到目的

import cProfile
import pstats
import os
# 性能分析装饰器定义
def do_cprofile(filename):
    """
    Decorator for function profiling.
    """
    def wrapper(func):
        def profiled_func(*args, **kwargs):
            # Flag for do profiling or not.
            DO_PROF = os.getenv("PROFILING")
            if DO_PROF:
                profile = cProfile.Profile()
                profile.enable()
                result = func(*args, **kwargs)
                profile.disable()
                # Sort stat by internal time.
                sortby = "tottime"
                ps = pstats.Stats(profile).sort_stats(sortby)
                ps.dump_stats(filename)
            else:
                result = func(*args, **kwargs)
            return result
        return profiled_func
    return wrapper

这样可以在想进行分析的地方进行性能分析, 例如想分析ProjectModel类中的get_project方法：

class ProjectModel(object):
    # ...
    # 应用装饰器来分析函数
    @do_cprofile("./mkm_run.prof")
    def get_project(self, **kwargs):
        # ...

装饰器函数中通过sys.getenv来获取环境变量判断是否需要进行分析，因此可以针对环境变量进行设置是否启动：

export PROFILING=y
# run the program...

程序跑完后便会在当前路径下生成mkm_run.prof的分析文件，可以通过打印或者可视化工具来对这个函数进行分析

三、性能分析报告

按照上面的方法，通过装饰器对get_project方法进行修饰来分析其性能，启动服务在触发执行get_project后，在当前路径下生成性能分析报告文件

mkm_run.prof是一个二进制文件，需要用python的pstats模块的接口来读取

import pstats

p = pstats.Stats('./mkm_run8.prof')
p.strip_dirs().sort_stats('cumtime').print_stats(100,1.0,'.*')

执行后获得的数据

Mon Jul 26 10:31:48 2021    mkm_run8.prof

         8408 function calls (8343 primitive calls) in 0.159 seconds

   Ordered by: cumulative time
   List reduced from 219 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.159    0.159 ProjectModel.py:83(get_project)
      128    0.002    0.000    0.135    0.001 connections.py:683(_read_packet)
      256    0.001    0.000    0.130    0.001 connections.py:728(_read_bytes)
      256    0.001    0.000    0.127    0.000 {method 'read' of '_io.BufferedReader' objects}
       31    0.000    0.000    0.126    0.004 socket.py:575(readinto)
       31    0.126    0.004    0.126    0.004 {method 'recv_into' of '_socket.socket' objects}
        2    0.000    0.000    0.119    0.059 ivResource.py:330(get_iv_detail)
       20    0.002    0.000    0.093    0.005 connections.py:442(_read_ok_packet)
        7    0.000    0.000    0.073    0.010 sqlUtil.py:80(query_one)
       10    0.000    0.000    0.053    0.005 SteadyDB.py:410(commit)

按照累积时间进行降序排序并输出了前十行，整个函数只运行了0.159秒
可见程序大部分时间主要花在数据库的连接中，其中获取解析sqlUtil过程是一个主要耗时的部分

四、分析数据可视化

虽然通过命令行可以查看函数调用关系，但是在黑白框中分析程序有些反人类，下面使用直观的可视化工具进行分析

4.1 gprof2dot

Gprof2Dot可将多种Profiler的数据转成Graphviz可处理的图像表述，配合dot命令即可得到不同函数所消耗的时间分析图

可以利用Gprof2Dot生成分析图：

gprof2dot -f pstats mkm_run.prof | dot -Tpng -o mkm_run.png

生成mkm_run.png分析图如下：

顺着浅色方格的看下去很容易发现程序的瓶颈部分

• 每个node的信息

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

• 每个edge的信息

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

4.2 vprof

vprof也是一个不错的工具来提供交互式的分析数据可视化

针对文件进行执行并分析，并在浏览器中生成可视化图标

# 生成CPU flame图
vprof -c c run.py