[Python] 性能分析--cProfile

1. 什么是性能分析

没有优化过的程序通常会在某些子程序(subroutine)上消耗大部分的CPU指令周期(CPU cycle)。性能分析就是分析代码和它正在使用的资源之间有着怎样的关系。例如,性能分析可以告诉你一个指令占用了多少CPU时间,或者整个程序消耗了多少内存。性能分析是通过使用一种被称为性能分析器(profiler)的工具,对程序或者二进制可执行文件(如果可以拿到)的源代码进行调整来完成的。

通常,当需要优化程序性能,或者程序遇到了一些奇怪的bug时(一般与内存泄漏有关),开发者会对他们的程序进行性能分析。这时,性能分析可以帮助开发者深刻地了解程序是如何使用计算机资源的(即可以细致到一个函数被调用了多少次)。

根据这些信息,以及对源代码的深刻认知,开发者就可以找到程序的性能瓶颈或者内存泄漏所在,然后修复错误的代码。

程序性能分析的作用主要有以下几个方面:

  • 发现性能瓶颈:通过性能分析,可以找到程序中的性能瓶颈,即程序中执行时间最长的部分,从而可以有针对性地进行优化,提高程序的执行效率。

  • 评估程序性能:通过性能分析,可以对程序的性能进行评估,了解程序的执行效率和资源占用情况,从而可以对程序进行优化和改进。

  • 比较不同实现方案的性能:通过性能分析,可以比较不同实现方案的性能,从而可以选择最优的实现方案,提高程序的执行效率。

  • 预测程序的性能:通过性能分析,可以预测程序在不同的环境下的性能表现,从而可以提前发现问题并进行优化。

  • 优化程序性能:通过性能分析,可以找到程序中的性能瓶颈,并进行优化,从而提高程序的执行效率,减少资源占用,提高用户体验。

帮助我们进行性能分析的工具便是性能分析器,它主要分为两类:

  1. 基于事件的性能分析(event-based profiling)
  2. 统计式的性能分析(statistical profiling)

1.1 基于事件的性能分析

不是所有的编程语言都支持这类性能分析。支持这类基于事件的性能分析的编程语言主要有以下几种。

  • Java:JVMTI(JVM Tools Interface,JVM工具接口)为性能分析器提供了钩子,可以跟踪诸如函数调用、线程相关的事件、类加载之类的事件。

  • .NET:和Java一样,.NET运行时提供了事件跟踪功能。

  • Python: 开发者可以用sys.setprofile函数,跟踪python_[call|return|exception]或c_[ call | return | exception ] 之类的事件。

基于事件的性能分析器(event-based profiler,也称为轨迹性能分析器,tracing profiler)是通过收集程序执行过程中的具体事件进行工作的。这些性能分析器会产生大量的数据。基本上,它们需要监听的事件越多,产生的数据量就越大。这导致它们不太实用,在开始对程序进行性能分析时也不是首选。但是,当其他性能分析方法不够用或者不够精确时,它们可以作为最后的选择。如果你想分析程序中所有返回语句的性能,那么这类性能分析器就可以为你提供完成任务应该有的颗粒度,而其他性能分析器都不能为你提供如此细致的结果。

1.2 统计式性能分析

统计式性能分析器以固定的时间间隔对程序计数器(program counter)进行抽样统计。这样做可以让开发者掌握目标程序在每个函数上消耗的时间。由于它对程序计数器进行抽样,所以数据结果是对真实值的统计近似。不过,这类软件足以窥见被分析程序的性能细节,查出性能瓶颈之所在。

这类性能分析软件的优点如下所示。

  • 分析的数据更少:由于我们只对程序执行过程进行抽样,而不用保留每一条数据,因此需要分析的信息量会显著减少。

  • 对性能造成的影响更小:由于使用抽样的方式(用操作系统中断),目标程序的性能遭受的干扰更小。虽然使用性能分析器并不能做到100%无干扰,但是统计式性能分析器比基于事件的性能分析器造成的干扰要小。

在Python中最常用的性能分析工具主要有:cProfiler, line_profiler以及memory_profiler 等。他们以不同的方式帮助我们分析Python代码的性能。这里主要关注Python内置的cProfiler

2. 一个简单的例子

以官方文档的一个简单例子来介绍该模块,通过简单的几行代码就可以对程序进行性能分析。

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

分析结果:

197 function calls (192 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:212(compile)
    1    0.000    0.000    0.001    0.001 re.py:268(_compile)
    1    0.000    0.000    0.000    0.000 sre_compile.py:172(_compile_charset)
    1    0.000    0.000    0.000    0.000 sre_compile.py:201(_optimize_charset)
    4    0.000    0.000    0.000    0.000 sre_compile.py:25    (_identityfunction)
3/1    0.000    0.000    0.000    0.000 sre_compile.py:33(_compile)

从分析报告结果中我们可以得到很多信息,包含了程序中的函数调用次数、总时间、平均时间、累计时间等。具体解释如下:

  1. 总共有197个函数调用,其中有192个是原始函数调用(primitive calls)。
  2. 程序总共执行了0.002秒。
  3. 按照函数名的字母顺序排序,显示了每个函数的调用次数、总时间、平均时间、累计时间等信息。
    • 第一列ncalls表示函数调用次数。
    • 第二列tottime表示函数总共执行的时间,不包括子函数的执行时间。
    • 第三列percall表示函数平均执行时间,等于tottime/ncalls。
    • 第四列cumtime表示函数总共执行的时间,包括子函数的执行时间。
    • 第五列percall表示函数平均执行时间,等于cumtime/ncalls。
    • 最后一列filename:lineno(function)表示函数所在的文件名、行号和函数名。

从这个性能分析结果可以看出,程序中最耗时的函数是re.py中的compile函数,它被调用了1次,总共执行了0.001秒,占据了程序总共执行时间的一半以上。因此,如果要优化程序的性能,就需要重点关注这个函数,找出其中的性能瓶颈并进行优化。

3. 进阶分析

Python进行性能分析最主要使用两个类:cProfile模块的Profile类和pstat模块的Stats类。

下面介绍下部分重要的函数

Profile类
cProfile模块的Profile类主要用于收集分析数据和创建分析结果

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

Stats类
pstats模块提供的Stats类可以帮助我们读取和操作stats文件(二进制格式)
Stats类可以接受stats文件名,也可以直接接受cProfile.Profile对象作为数据源。

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

通过利用这两个类,可以更加自由地使用性能分析,可以针对某一部分代码使用性能分析,并使用Stats类进一步对分析结果进行整合和处理,下面给出一个使用的例子模板:

import cProfile, pstats, io
pr = cProfile.Profile()
pr.enable()
# ---- do something ----
create_main_window()
# ---- do something ----
pr.disable()
with open("time_cost.txt","w+") as f:
    ps = pstats.Stats(pr, stream=f).sort_stats(2)
    ps.print_stats()

将需要分析的代码放在do something的部分中,即可获得对该部分代码的性能分析。其中sort_stats(2)代表按照cumtime(累计时间)排序。

4. 模块化封装

在上面的基础上,我们已经可以很方便的进行性能分析。但是,每次使用时都要加上一大段代码,在测试完毕后再将其删除,显然是不够简洁和方便。因此,我们可以通过写一个带有参数的装饰器,这样想分析项目中任何一个函数,便可方便的使用装饰器来达到目的。

import cProfile
import pstats
from functools import wraps
import os

def profile(sort_by='cumulative', lines=10, filename=None):
    def decorator(func):
        @wraps(func)
        def wrapper(*args, **kwargs):
            PROF_FLAG = os.getenv("PROFILING")
            if PROF_FLAG:
                profiler = cProfile.Profile()
                profiler.enable()
                result = func(*args, **kwargs)
                profiler.disable()
                stats = pstats.Stats(profiler).sort_stats(sort_by)
                stats.print_stats(lines)
                if filename:
                    stats.dump_stats(filename)
                else:
                    result = func(*args, **kwargs)
            return result
        return wrapper
    return decorator

这个装饰器接受三个参数:sort_by、lines和filenamesort_by表示按照哪个指标进行排序,默认为'cumulative',表示按照函数的累计时间进行排序;lines表示显示多少行结果,默认为10;filename表示将分析结果存储到哪个文件中,默认为None,表示不存储。

使用方法如下:

@profile(sort_by='cumulative', lines=20, filename='result.prof')
def my_function():
    # 函数代码

# 调用函数时自动执行性能分析
my_function()

装饰器函数中通过sys.getenv来获取环境变量判断是否需要进行分析,只需通过设置环境变量来告诉程序是否进行性能分析,当测试完毕后无需删除代码,只需更改环境变量即可。

export PROFILING=y
# run the program...

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

5. 结果分析

按照上文的方法,我们通过装饰器对运行的函数进行修饰来进行性能分析,这样我们便可以像正常一样去跑程序,但是不同的是当前路径下会生成性能分析报告文件。

生成的这个文件为.prof文件,它是一个二进制文件,一个简单的读取方式是用python的pstats模块的接口来读取。

ps = pstats.Stats("filename").sort_stats(2)
ps.print_stats()

但是,从这样的数据中继续分析下去显然是相当痛苦和反人类的,不过好在有着很多现成好用的可视化工具可以帮助我们继续分析下去,比如gprof2dot、vprof、pyflame等。这边主要下介绍gprof2dot,个人觉得是用起来最习惯的。其他两个只给出示例图和链接以供参考。

5.1 gprof2dot

Gprof2Dot是一个Python脚本,可以可将多种Profiler的数据转换成Graphviz格式的图形化展示,方便用户进行性能分析和优化。

下载安装及详细用法:https://github.com/jrfonseca/gprof2dot

通过该脚本可以获得程序运行不同函数的时间分析图:

gprof2dot -f pstats filename.prof | dot -Tpng -o out.png

执行后就可以在同一路径下看到生成好的分析图 out.png

5.2 vprof

下载安装及详细用法:https://github.com/nvdv/vprof

5.3 pyflame

Pyflame是一个轻量级的Profiler工具,可以帮助用户分析Python程序的性能瓶颈,并可视化地显示函数调用关系和执行时间。Pyflame支持多种输出格式,包括FlameGraph、SVG等。

下载安装及详细用法:https://github.com/uber-archive/pyflame