Python性能测试基础

测试

本文中我们来看看在Python中如何做基本的性能测试。

在编程领域中对于性能这个词，有很多评估的角度，比如CPU时间、内存消耗、磁盘I/O、网络带宽等，本文将从CPU时间和内存消耗两个方面来介绍如何对Python程序进行性能分析。

首先我们需要一段测试代码，我们使用判断一个给定的数字是否是素数的函数isPrime来做测试，这是一段CPU密集型的代码：

1
2
3
4
5
6
7
8
9
import math    

def isPrime(n):
	if n <= 1:
		return False
	for i in range(2, int(math.sqrt(n)) + 1):
		if n % i == 0:
			return False
	return True

下面的一部分测试将使用isPrime函数。

使用装饰器测量函数运行时间

代码如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
from functools import wraps
import time

def timeit(fn):
	@wraps(fn)
	def timeit_(*args, **kwargs):
		t1 = time.time()
		res = fn(*args, **kwargs)
		t2 = time.time() 
		print(fn.__name__ + " took " + str(t2-t1) + " seconds")
		return res
	return timeit_

@timeit
def test():
	l1 = [0] * 1000000
	l2 = [0] * 10000000
	l3 = [0] * 100000000

if __name__ == "__main__":
    res = test()

执行后输出：

1
test took 0.7034409046173096 seconds

使用装饰器是比较方便的做法，不过装饰器也只能打印整个函数的执行时间，测试粒度较粗。

使用timeit模块测试一段代码的CPU时间

直接看代码：

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
#!/usr/bin/python
#coding=utf-8

import math  
import timeit
  
def isPrime(n):
	if n <= 1:
		return False
	for i in range(2, int(math.sqrt(n)) + 1):
		if n % i == 0:
			return False
	return True

def fn():
	start = 1
	end = 2000000
	cnt = 0
	for i in range(start, end + 1, 1):
   		res = isPrime(i)
   		if res:
   			cnt += 1
	print("There are " + str(cnt) + " primes in the " + str(start) + "-" + str(end) + " range.")

if __name__ == "__main__":
	t = timeit.timeit(stmt=fn, number=1)
	print(t)

我们计算2000000以内的素数个数，在我的Mac笔记本上耗时如下：

12.233505398966372

执行期间如果你打开活动监视器会发现该Python进程占用的CPU内核使用率达到99%以上，因为isPrime函数是CPU密集型的。

timeit模块还有很多用法，具体信息可以查阅相关文档。

使用timeit模块来测量一段代码能直观地获得执行这段代码的总耗时，这是比较粗粒度的测量，我们无法得知其中每行代码的耗时占比。因此这种方式只能在前期粗略地帮我们搜集一些代码整体执行时间的数据，如果要深入分析还是要想其他办法。

使用UNIX的time命令进行简单的计时

类UNIX操作系统提供了time命令来对一个程序的执行进行计时，我们把代码修改成下面这样：

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
#!/usr/bin/python
#coding=utf-8

import math  
import timeit
  
def isPrime(n):
	if n <= 1:
		return False
	for i in range(2, int(math.sqrt(n)) + 1):
		if n % i == 0:
			return False
	return True

def fn():
	start = 1
	end = 2000000
	cnt = 0
	for i in range(start, end + 1, 1):
   		res = isPrime(i)
   		if res:
   			cnt += 1
	print("There are " + str(cnt) + " primes in the " + str(start) + "-" + str(end) + " range.")

if __name__ == "__main__":
	fn()

我们在shell中执行（注意要使用/usr/bin/time来引用time命令，否则会引用到shell内建的time命令，后者对我们的性能测试意义不大）：

1
/usr/bin/time -p python prime_numbers.py

获得如下输出：

real        13.96
user        13.75
sys          0.09

time命令输出了三行，其中real表示总耗时，user表示CPU花费在实际任务上的时间，这其中不包括陷入内核中执行的时间，sys表示陷入内核执行的时间。

需要注意的是，上例中/usr/bin/time记录的时间包括了启动Python解释器的时间。

使用cProfile模块

python -m cProfile profile.stats prime_numbers.py

下面的命令使用cProfile模块对prime_numbers.py进行分析：

1
python -m cProfile -s cumulative prime_numbers.py

输出如下：

1
2
3
4
5
6
7
8
9
10
11
4000509 function calls (4000503 primitive calls) in 14.028 seconds

Ordered by: cumulative time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    2/1    0.000    0.000   14.028   14.028 {built-in method builtins.exec}
    1    0.000    0.000   14.028   14.028 test2.py:1(<module>)
    1    0.405    0.405   14.027   14.027 test2.py:12(fn)
2000000   13.398    0.000   13.622    0.000 test2.py:4(isPrime)
1999999    0.224    0.000    0.224    0.000 {built-in method math.sqrt}
...

这里只截取前面几行最重要的输出信息，输出结果中每列的含义：

  • ncalls：函数被调用了总次数
  • tottime：函数执行的总时间（不包括其下的子函数）
  • percall：函数单次执行的时间（不包括其下的子函数），即tottime/ncalls
  • cumtime：函数执行的总时间（包括其下的子函数）
  • percall：函数单次执行的时间（包括其下的子函数），即cumtime/ncalls
  • filename:lineno(function)：函数的基本信息

使用line_profile对代码进行逐行分析

先安装line_profile：

1
pip install line_profiler

这次我们使用另一端代码，这段代码主要是创建了3个列表，列表长度分别是一百万、一千万和一亿，并且对要测试的函数line_test加上@profile装饰器：

1
2
3
4
5
6
7
8
9
10
11
#!/usr/bin/python
#coding=utf-8

@profile
def line_test():
	l1 = [0] * 1000000
	l2 = [0] * 10000000
	l3 = [0] * 100000000

if __name__ == "__main__":
    line_test()

下面的命令使用line_profile模块对line_test.py进行分析：

1
kernprof -l -v line_test.py

你可能会奇怪我们并没有手动引入profile怎么能运行，其实当执行kernprof时，kernprof会自动将profile注入到__builtins__命名空间中。

输出结果如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
Wrote profile results to line_test.py.lprof
Timer unit: 1e-06 s

Total time: 0.582631 s
File: line_test.py
Function: line_test at line 6

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     6                                           @profile
     7                                           def line_test():
     8         1       3440.0   3440.0      0.6  	l1 = [0] * 1000000
     9         1      54167.0  54167.0      9.3  	l2 = [0] * 10000000
    10         1     525024.0 525024.0     90.1  	l3 = [0] * 100000000

来看看上面输出结果中每列的含义：

  • Line #：代码行号，这里的代码行号和源代码文件中的行号是完全一致的
  • Hits：代码行的执行次数
  • Time：该代码行的总执行时间
  • Per Hit：该代码行每次执行的时间
  • % Time：代码行执行时间占整个程序执行时间的比率
  • Line Contents：具体代码行

这些输出信息非常直观，比如你会发现第10行创建长度为一亿的列表占用了90%的时间，当你对你自己的代码做line_profile时，根据这些信息很容易发现哪部分代码执行时间比较长，可以着重优化。

使用memory_profile诊断内存使用量

先安装memory_profile：

1
pip install memory_profiler

这次我们使用另一端代码，这段代码主要是创建了3个列表，列表长度分别是一百万、一千万和一亿，并且对要测试的函数memory_test加上@profile装饰器：

1
2
3
4
5
6
7
8
9
10
11
12
13
#!/usr/bin/python
#coding=utf-8

from memory_profiler import profile

@profile
def memory_test():
	l1 = [0] * 1000000
	l2 = [0] * 10000000
	l3 = [0] * 100000000

if __name__ == "__main__":
    memory_test()

下面的命令使用memory_profile模块对memory_test.py进行分析：

1
python -m memory_profiler memory_test.py

输出如下：

1
2
3
4
5
6
7
8
9
Filename: memory_test.py

Line #    Mem usage    Increment   Line Contents
================================================
     6     34.2 MiB     34.2 MiB   @profile
     7                             def memory_test():
     8     41.8 MiB      7.6 MiB   	l1 = [0] * 1000000
     9    118.1 MiB     76.3 MiB   	l2 = [0] * 10000000
    10    881.0 MiB    762.9 MiB   	l3 = [0] * 100000000

输出结果中每列的含义：

  • Line #：代码行号，这里的代码行号和源代码文件中的行号是完全一致的
  • Mem usage：当前程序使用的总内存大小
  • Increment：内存增长的大小，即和上一行代码相比，执行本行代码导致的内存增量
  • Line Contents：具体代码行

memory_profile的输出结果也很好理解，可以依据代码行来观察具体的内存增量，比如上例中第10行代码创建了长度为一亿的列表，占用了比较多的内存，其Increment是762.9 MiB。需要注意的是，MiB表示的是2^20字节，这和MB有所区别。

用heapy调查堆上的对象

先安装依赖:

1
pip install guppy

需要注意的是heapy不支持Python 3.x，所以我们在Python 2.7上测试。

测试代码如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
#!/usr/bin/python
#coding=utf-8

def heapy_test():
	l1 = [0] * 1000000
	from guppy import hpy
	hp = hpy()
	h = hp.heap()
	print h
	print

	l2 = [0] * 10000000
	h = hp.heap()
	print h
	print

	l3 = [0] * 100000000
	h = hp.heap()
	print h
	print

if __name__ == "__main__":
    heapy_test()

输出结果如下：

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
41
Partition of a set of 26265 objects. Total size = 11526656 bytes.
 Index  Count   %     Size   % Cumulative  % Kind (class / dict of class)
     0    178   1  8152080  71   8152080  71 list
     1  11976  46   985344   9   9137424  79 str
     2   5969  23   481488   4   9618912  83 tuple
     3    323   1   277448   2   9896360  86 dict (no owner)
     4     69   0   219768   2  10116128  88 dict of module
     5   1653   6   211584   2  10327712  90 types.CodeType
     6    200   1   211136   2  10538848  91 dict of type
     7   1615   6   193800   2  10732648  93 function
     8    200   1   177912   2  10910560  95 type
     9    124   0   135328   1  11045888  96 dict of class
<90 more rows. Type e.g. '_.more' to view.>

Partition of a set of 26274 objects. Total size = 95415008 bytes.
 Index  Count   %     Size   % Cumulative  % Kind (class / dict of class)
     0    179   1 92038232  96  92038232  96 list
     1  11978  46   985472   1  93023704  97 str
     2   5968  23   481424   1  93505128  98 tuple
     3    329   1   279128   0  93784256  98 dict (no owner)
     4     69   0   219768   0  94004024  99 dict of module
     5   1653   6   211584   0  94215608  99 types.CodeType
     6    200   1   211136   0  94426744  99 dict of type
     7   1614   6   193680   0  94620424  99 function
     8    200   1   177912   0  94798336  99 type
     9    124   0   135328   0  94933664  99 dict of class
<90 more rows. Type e.g. '_.more' to view.>

Partition of a set of 26275 objects. Total size = 900721480 bytes.
 Index  Count   %     Size   % Cumulative  % Kind (class / dict of class)
     0    180   1 897344672 100 897344672 100 list
     1  11978  46   985472   0 898330144 100 str
     2   5968  23   481424   0 898811568 100 tuple
     3    329   1   279128   0 899090696 100 dict (no owner)
     4     69   0   219768   0 899310464 100 dict of module
     5   1653   6   211584   0 899522048 100 types.CodeType
     6    200   1   211136   0 899733184 100 dict of type
     7   1614   6   193680   0 899926864 100 function
     8    200   1   177912   0 900104776 100 type
     9    124   0   135328   0 900240104 100 dict of class
<90 more rows. Type e.g. '_.more' to view.>

上面的结果是按照在堆上分配内存的大小来排序的。

测试