cProfile是Python 2.5之后标准版Python解释器默认的性能分析器。cProfile可以统计每个函数消耗CPU时间,同时还提供其他细节,如函数被调用次数等。

cProfile的一个示例:

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

代码输出为

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40

194 function calls (189 primitive calls) in 0.000 seconds

Ordered by: standard name

ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.000 0.000 <string>:1(<module>)
1 0.000 0.000 0.000 0.000 re.py:188(compile)
1 0.000 0.000 0.000 0.000 re.py:226(_compile)
1 0.000 0.000 0.000 0.000 sre_compile.py:178(_compile_charset)
1 0.000 0.000 0.000 0.000 sre_compile.py:207(_optimize_charset)
4 0.000 0.000 0.000 0.000 sre_compile.py:24(_identityfunction)
3/1 0.000 0.000 0.000 0.000 sre_compile.py:32(_compile)
1 0.000 0.000 0.000 0.000 sre_compile.py:359(_compile_info)
2 0.000 0.000 0.000 0.000 sre_compile.py:472(isstring)
1 0.000 0.000 0.000 0.000 sre_compile.py:478(_code)
1 0.000 0.000 0.000 0.000 sre_compile.py:493(compile)
5 0.000 0.000 0.000 0.000 sre_parse.py:126(__len__)
12 0.000 0.000 0.000 0.000 sre_parse.py:130(__getitem__)
7 0.000 0.000 0.000 0.000 sre_parse.py:138(append)
3/1 0.000 0.000 0.000 0.000 sre_parse.py:140(getwidth)
1 0.000 0.000 0.000 0.000 sre_parse.py:178(__init__)
10 0.000 0.000 0.000 0.000 sre_parse.py:182(__next)
2 0.000 0.000 0.000 0.000 sre_parse.py:195(match)
8 0.000 0.000 0.000 0.000 sre_parse.py:201(get)
1 0.000 0.000 0.000 0.000 sre_parse.py:301(_parse_sub)
2 0.000 0.000 0.000 0.000 sre_parse.py:379(_parse)
1 0.000 0.000 0.000 0.000 sre_parse.py:67(__init__)
1 0.000 0.000 0.000 0.000 sre_parse.py:675(parse)
3 0.000 0.000 0.000 0.000 sre_parse.py:90(__init__)
1 0.000 0.000 0.000 0.000 {_sre.compile}
15 0.000 0.000 0.000 0.000 {isinstance}
38/37 0.000 0.000 0.000 0.000 {len}
2 0.000 0.000 0.000 0.000 {max}
48 0.000 0.000 0.000 0.000 {method 'append' of 'list' objects}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
1 0.000 0.000 0.000 0.000 {method 'get' of 'dict' objects}
1 0.000 0.000 0.000 0.000 {method 'items' of 'dict' objects}
8 0.000 0.000 0.000 0.000 {min}
6 0.000 0.000 0.000 0.000 {ord}

  1. 第一行告诉我们一共有194个函数被调用,其中189个是原生(primitive)调用,表明这些调用不涉及递归。
  2. ncalls表示函数的调用次数,如果这一列有两个数值,表示有递归调用,第一个是总调用次数,第二个是原生调用次数。
  3. tottime是函数内部消耗的总时间(不包括调用其他函数的时间)。
  4. percall是tottime除以ncalls,表示每次调用平均消耗时间。
  5. cumtime是之前所有子函数消耗时间的累积和。
  6. percall是cumtime除以原生调用的数量,表示该函数调用时,每个原生调用的平均消耗时间。
  7. filename:lineno(function)为被分析函数所在文件名、行号、函数名。

cProfile提供的方法

run 函数

1
profile.run(command, filename=None, sort=-1)

当这个函数被调用时,会执行如下方法:

1
exec(command, __main__.__dict__, __main__.__dict__)

如果没有设置文件名filename,则会自动创建一个新的stats类的实例并打印一个简单的解析报告。指定文件名后会将解析报告保存在名为filename的文件中,该文件是一个二进制文件,需要使用Stats类进行处理。

runctx函数

1
profile.runctx(command, globals, locals, filename=None)

这个函数与profile.run函数类似,唯一不同为参数列表中支持两个字典参数:globals和locals。当这个函数被调用时,会执行如下函数:

1
exec(command, globals, locals)

与run函数的区别:

运行下面代码时

1
2
3
4
5
import cProfile
def runRe():
import re
cProfile.run('re.compile("foo|bar")')
runRe()

程序会出错,提示: Name Error: name ‘re’ is not defined

当将上述代码改为

1
2
3
4
5
import cProfile
def runRe():
import re
cProfile.runctx('re.compile("foo|bar")', None, locals())
runRe()

程序正常运行。

Profile类

1
profile.Profile(timer=None, timeunit=0.0, subcalls=True, builtins=True)

其中,timer参数是一个自定义函数,可以设置为与默认函数不同的方式测量时间,必须是一个可以返回当前时间数值的函数。当timer返回一个整数,timeunit参数表示单位时间换算成秒的系数。如返回值时间单位是毫秒,timeunit应该为.001。该类会返回一个类,提供了比run和runctx更多的控制。返回类的其他方法包括:

  • enable(): 开始收集性能分析数据
  • disable(): 停止收集性能分析数据
  • create_stats(): 停止收集性能分析数据,并为已收集的数据创建stats对象
  • print_stats(sort=-1): 创建一个stats对象,打印分析结果
  • dump_stats(filename): 把当前性能分析的内容写进一个文件
  • run(cmd): 与cProfile.run函数类似
  • runctx(cmd, globals, locals): 与cProfile.runctx函数类似
  • runcall(func, args, *kwargs): 收集被调用函数func的性能分析数据

一个实例:

1
2
3
4
5
6
7
8
9
10
11
import cProfile

def runRe():
import re
re.compile("foo|bar")

prof = cProfile.Profile()
prof.enable()
runRe()
prof.create_stats()
prof.print_stats()

可以看到,使用profile.Profile减少了性能分析代码对原来代码的影响。

对整个文件进行性能分析

如果不想更改源代码,可以在运行Python脚本时加一些参数对整个Python脚本进行性能分析

1
python -m cProfile your_script.py -o you_script.profile

Stats类

pstats模块中的Stats类可以读取和操作cProfile得到的性能分析报告保存的stats文件。

一个使用Stats类解析stats文件的示例:

1
2
3
import pstats
p = pstats.Stats('stats')
p.strip_dirs().sort_stats(-1).print_stats()

Stats对象的方法有:

  • strip_dirs(): 删除报告中所有函数的路径信息
  • add(*filenames): 将文件名对应的文件的信息加载到当前的stats对象中
  • dump_stats(filename): 吧加载到stats类的数据保存在文件中
  • sort_stats(*keys): 对所有项目按照一系列条件进行排序
  • reverse_order(): 逆反原来参数的排序方法
  • print_stats(*restrictions): 把信息打印到STDOUT中
  • print_callers(*restrictions): 显示程序执行过程中每个函数的调用次数、总时间、累计时间、文件名、行号和函数名的组合
  • print_callees(*restrictions): 打印一列调用其他函数的函数

优化示例

我们通过计算斐波那契数列来演示如何通过cProfile来优化程序。

首先,使用递归的方式计算斐波那契数列的前30个数:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
#!/usr/bin/env python
# encoding: utf-8

import cProfile

def fib(n):
if n <= 1:
return n
else:
return fib(n-1) + fib(n-2)

def fib_seq(n):
return [fib(i) for i in range(n)]

cProfile.run('fib_seq(30)')

代码的输出结果为:

1
2
3
4
5
6
7
8
9
10
         4356590 function calls (34 primitive calls) in 1.032 seconds

Ordered by: standard name

ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 1.032 1.032 <string>:1(<module>)
1 0.000 0.000 1.032 1.032 fib1.py:12(fib_seq)
4356586/30 1.032 0.000 1.032 0.034 fib1.py:6(fib)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
1 0.000 0.000 0.000 0.000 {range}

可以看出

  • 程序运行时间为1.032秒;
  • 共有4356590个函数调用,其中,原生调用(不包括递归)只有34个;
  • 在代码的第6行,共有4356586-30=4356556次递归调用;
  • 从cumtime也可以看出,程序所有的时间都消耗在第6行fib函数中

下面,我们通过对fib函数增加一个装饰器,缓存之前计算的值,来减少递归调用次数,代码为:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
#!/usr/bin/env python
# encoding: utf-8

import cProfile

class cached:
def __init__(self, fn):
self.fn = fn
self.cache = {}

def __call__(self, *args):
try:
return self.cache[args]
except KeyError:
self.cache[args] = self.fn(*args)
return self.cache[args]

@cached
def fib(n):
if n <= 1:
return n
else:
return fib(n-1) + fib(n-2)

def fib_seq(n):
return [fib(i) for i in range(n)]

cProfile.run('fib_seq(30)')

程序运行结果为:

1
2
3
4
5
6
7
8
9
10
11
      120 function calls (64 primitive calls) in 0.000 seconds

Ordered by: standard name

ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.000 0.000 <string>:1(<module>)
86/30 0.000 0.000 0.000 0.000 fib2.py:11(__call__)
30 0.000 0.000 0.000 0.000 fib2.py:18(fib)
1 0.000 0.000 0.000 0.000 fib2.py:25(fib_seq)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
1 0.000 0.000 0.000 0.000 {range}

可以看出,程序的函数调用从4356590降到120个,运行时间也变成几乎不耗时,递归调用也减少了很多。

更多关于cProfile的介绍与用法,请查看Python官方文档的介绍。