Python基础(11) 性能测试工具 cProfile

0. 前言

• 基本需求：统计程序每一部分的运行时间。
  • 其实，性能测试应该还包括内存占用统计等，但暂时并不关心。
  • 所谓“程序每一部分”有很多中理解，比如按“函数”统计，或按“每行代码”统计。
  • cProfile 就是用按“函数”统计运行时间。
• cProfile的特点
  • 会统计每个函数的总运行时间（包括子函数）、除自函数外的运行时间、运行次数、每次平均运行时间。
  • 默认情况下，只统计主线程的运行时间。
  • 如果想要统计多线程/进程的运行时间，需要对每个线程/进程分别执行cProfile的API。
• 参考资料
  • Python官方文档：The Python Profilers
  • StackOverflow: How can you profile a Python script?
  • StackOverflow: Python multipoocess profiling
  • Python优化第一步: 性能分析实践

1. cProfile 的使用

1.1. API 介绍

• profile.run(command, filename=None, sort=-1)
  • command是字符串形式，包含python代码。
• profile.runctx(command, globals, locals, filename=None, sort=-1)
  • 与上面的函数基本相同，就是添加了上下文信息（即本地变量与全局变量集合）
• profile.Porfile(timer=None, timeunit=0.0, subcalls=True, builtins=True)
  • 本函数用于更精细的性能测试。
  • 该类主要包含的方法有 enable/disable/create_stats/print_stats/dump_stats/run/runctx/runcall
  • runcall方法调用的是函数，而不是一个字符串。

1.2. 单线程使用

• 直接通过命令行运行：
  • 命令 python -m cProfile [-o output_file] [-s sort_order] (-m module | myscript.py)
  • 特点：使用方便，不需要额外编写源码，但只能监控主线程的运行时间。
• 通过编程处理
  • 其实就是通过 run方法执行需要测试的函数即可。

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

• 通过 cPorilfe.Profile 类实现

import cProfile, pstats, io
from pstats import SortKey
pr = cProfile.Profile()
pr.enable()
# ... do something ...
pr.disable()
s = io.StringIO()
sortby = SortKey.CUMULATIVE
ps = pstats.Stats(pr, stream=s).sort_stats(sortby)
ps.print_stats()
print(s.getvalue())

1.2. 多线程使用

• cPorfile的文档里完全没说过不支持多线程的性能测试，更没提过在多线程下怎么使用了
• 实现思路：为每个线程提供不同的 cprofile.Profile类。
• 实现方法一：参考这里
  • 使用自定义线程类替代原始线程类，即重写run方法，创建cprofile.Profile类并导出结果。
  • 特点：每个线程都必须使用该类创建，不然就不能进行性能测试。对于一直第三方包自主创建线程就无法处理。

class ProfiledThread(threading.Thread):
    # Overrides threading.Thread.run()
    def run(self):
        profiler = cProfile.Profile()
        try:
            return profiler.runcall(threading.Thread.run, self)
        finally:
            profiler.dump_stats('myprofile-%d.profile' % (self.ident,))

• 实现方法二：参考这里
  • 源代码是多进程的，但相信多线程也是一样的。
  • 没有继承类，对运行的函数进行了一次包装，可能用起来比上面那种稍微方便一点。
  • 但也存在相同的问题，即要能控制线程/进程的创建。

import multiprocessing
import cProfile
import time
def test(num):
    time.sleep(3)
    print 'Worker:', num

def worker(num):
    cProfile.runctx('test(num)', globals(), locals(), 'prof%d.prof' %num)


if __name__ == '__main__':
    for i in range(5):
        p = multiprocessing.Process(target=worker, args=(i,))
        p.start()

2. 结果解释以及可视化

2.1. 结果详解

• 下面是官网给的一个输出结果样例
  • ncalls 函数调用次数
  • tottime 函数运行时间（不包括单独计算的子函数）
  • percall 每次调用平均运行时间
  • cumtime 函数累计运行时间（包括子函数）
  • percall 每次调用平均运行时间
  • filename:lineno(function) 文件名/行数以及对应的函数名

      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)

2.2. 可视化工具 - snakeviz

• 使用：

  • 第一步，安装 pip install snakeviz
  • 第二步，选择日志文件，运行命令 snakeviz log.profile
  • 第三步，打开浏览器查看。

• 有两种展示方式：

  • ICICLE
  • SUNBURST