Python代码性能分析（后篇）

前言

在前一篇文章中，我介绍了测量执行Python代码所需要的总体时间的几种方法。而在实际的性能分析场景中，目标代码的逻辑往往比较复杂，光靠总体执行耗时并不能帮助我们快速定位性能瓶颈。这个时候就需要请出Python的标准库：cProfile（官方文档）来对代码进行细致的性能分析了。
和前一篇文章一样，本文所使用的测试平台为Ubuntu 18.04+Python 3.6，并使用代码文件slow_func.py作为样例进行性能分析，内容如下：

# coding:utf-8
import time
import random

def func1():
    time.sleep(1)  # 等待一秒

def func2():
    for _ in range(2 ** 24):
        random.random()  # 生成1600万个随机数

if __name__ == '__main__':
    func1()
    func2()

命令行使用cProfile

对于单独的Python代码文件来说，通过命令行使用cProfile无疑是最方便的选择。
执行如下shell命令：

python3 -m cProfile -s tottime slow_func.py

首先用python3的-m选项调用cProfile模块，然后用cProfile的-s选项让输出结果按tottime进行排序，最后执行slow_func.py文件。
完整调用格式为：python -m cProfile [-o output_file] [-s sort_order] myscript.py

得到如下结果：

        16778563 function calls (16778520 primitive calls) in 3.176 seconds

  Ordered by: internal time

  ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       1    1.456    1.456    2.172    2.172 slow_func.py:8(func2)
       1    1.001    1.001    1.001    1.001 {built-in method time.sleep}
16777216    0.716    0.000    0.716    0.000 {method 'random' of '_random.Random' objects}
       1    0.001    0.001    0.001    0.001 {built-in method _imp.create_dynamic}
       3    0.000    0.000    0.000    0.000 {built-in method marshal.loads}
       # ...省略后续100多行

• 输出的第1行表明，脚本文件执行中存在1600多万次的函数调用，共耗费3.268秒。
  • 而根据前一篇文章的测试结果，直接执行该脚本文件只需要2秒左右的时间，那多出来的1秒多花在了哪里？这是因为cProfile需要对每一次函数调用进行监控和记录，由于该文件存在较多的函数调用，所以总执行耗时也就增长了许多了。
• 第3行表明，下表内容按照internal time（内部执行时间，tottime）排序，这是由执行命令中的-s tottime参数决定的。
• 第5行为分析结果表的表头，依次为ncalls：调用次数、tottime：内部执行耗时、percall：内部执行耗时/调用次数、cumtime：累计执行耗时、percall：累计执行耗时/调用次数，以及最后的文件名+行号+函数名称。
  • tottime和cumtime的区别在于，tottime不包括子函数执行所花费的时间，而cumtime是包括的。
• 第6行表明，slow_func.py中第8行的func2函数共执行了1次，内部耗时1.456秒，累计耗时2.172秒。
• 第7行表明，Python内置的sleep函数共执行了一次，耗时1.001秒。
• 第8行表明，Python内置的random函数共执行了1600多万次，耗时0.716秒。
  • 由于random函数是被func2函数调用的，所以这0.716秒和func2函数的内部执行耗时1.456秒，共同组成了func2函数的累计执行耗时：2.172秒。
• 由于是用cProfile分析整个脚本文件，所以许多Python自身所需的函数调用也被展示在了结果里，所以分析结果表才会有100多行的规模。这个问题可以在下一小节中解决。

代码里使用cProfile

从本质上来说，通过命令行使用cProfile相当于在代码里使用cProfile的一个简化操作。而在命令行里分析代码有着明显的局限性：目标代码必须独立成文件、输出格式固定等等。所以，在代码里使用cProfile往往是一个更优的选择。
执行如下Python代码：

import cProfile
import pstats
from io import StringIO

from slow_func import func1, func2

profile = cProfile.Profile()
profile.enable()  # 分析开始
func1()
func2()
profile.disable()  # 分析结束
ram_file = StringIO()
sort_by = 'tottime'
stats = pstats.Stats(profile, stream=ram_file)  # 读取结果
stats.strip_dirs().sort_stats(sort_by).print_stats()  # 按格式输出至ram_file

print(ram_file.getvalue())

代码的核心逻辑是使用cProfile模块的Profile类对代码块进行性能分析，分析完成后使用pstats模块的Stats类将分析结果按一定格式写入至内存文件，最后输出该文件里写入的内容。
实际上这只是一个较为简单的样例，pstats模块还可以获得函数之间的调用关系、将结果持久化、显示文件路径等等，更完整的说明可以参考官方文档。

得到如下结果：

        16777220 function calls in 3.225 seconds

  Ordered by: internal time

  ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       1    1.517    1.517    2.224    2.224 slow_func.py:8(func2)
       1    1.001    1.001    1.001    1.001 {built-in method time.sleep}
16777216    0.707    0.000    0.707    0.000 {method 'random' of '_random.Random' objects}
       1    0.000    0.000    1.001    1.001 slow_func.py:5(func1)
       1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

cProfile结果可视化

一般来说，通过以上两个例子就可以获得完善的性能分析报告了。但通过一些可视化工具对cProfile 的报告进行二次处理，我们可以更清晰地观察函数之间的调用关系、更轻松地找出性能瓶颈，算是一个不错的辅助手段。在这里只介绍一种可视化工具：JetBrain PyCharm自带的Profile工具。

• 点击Pycharm中Run菜单里的Profile 'xxx'项目，即可对当前运行执行方案使用cProfile进行性能分析，如下图：
  

• 结果如下图所示。其中，Time对应cProfile中的cumtime，即累计执行耗时；Own Time对应cProfile中的tottime，即内部执行耗时。