正文
Python: 对程序做性能分析及计时统计
提示：扫一扫查出行【扫一扫了解最新限行尾号】
复制提示
1.对整个程序的性能分析
如果只是想简单地对整个程序做计算统计，通常使用UNIX下的
time
命令就足够了。
(base) ➜ Learn-Python time python someprogram.py
python someprogram.py 0.10s user 0.01s system 98% cpu 0.117 total
由于我用的是Mac系统，和Linux系统的输出可能有不同，不过关键都是这三个时间：
-
user : 运行用户态代码所花费的时间，也即CPU实际用于执行该进程的时间，其他进程和进程阻塞的时间不计入此数字。
-
system : 在内核中执行系统调用（如I/O调用）所花费的CPU时间。
-
total (Linux下应该是 real ):即挂钟时间(wall-clock time)，也称响应时间(response time)、消逝时间(elapsed time)，是进程运行开始到结束所有经过的时间，包括了进程使用的时间片和进程阻塞的时间（例如等待I/O完成）。
请注意，若user + system > total，可能存在多个处理器并行工作；
若user + system < total，则可能在等待磁盘、网络或其它设备的响应。
也就说上面这个程序的挂钟时间为0.251s，CPU实际用于执行该进程的时间为0.24s，用于系统调用的时间为0.01s。
再来看看另外一个极端，如果想针对程序的行为产生一份详细的报告，那么可以使用
cProfile
模块：
(base) ➜ Learn-Python python -m cProfile someprogram.py
7 function calls in 0.071 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.002 0.002 0.071 0.071 someprogram.py:1(<module>)
1 0.039 0.039 0.068 0.068 someprogram.py:1(func1)
1 0.029 0.029 0.029 0.029 someprogram.py:3(<listcomp>)
1 0.000 0.000 0.001 0.001 someprogram.py:7(func2)
1 0.000 0.000 0.000 0.000 someprogram.py:9(<listcomp>)
1 0.000 0.000 0.071 0.071 {built-in method builtins.exec}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
可见我们上述代码的热点是在于
func1
函数。
这里再多说几句，这里传入的
-m -cProfile
可选参数意为将Python的
cPofile
模块做为脚本运行，实际上等价于：
python /Users/orion-orion/miniforge3/lib/python3.9/cProfile.py someprogram.py
当然，中间那个路径取决于大家各自的环境。这也就是说我们将
some_program.py
做为
cProfile.py
程序的输入参数，目的就是对其进行性能分析。
2.对特定代码段做性能分析
2.1 分析函数和语句块
不过对于做代码性能分析而言，更常见的情况则处于上述两个极端情况之间。
比如，我们可能已经知道了代码把大部分运行时间都花在几个某几个函数上了。要对函数进行性能分析，使用装饰器就能办到。示例如下：
import time
from functools import wraps
def timethis(func):
@wraps(func)
def wrapper(*args, **kwargs):
start = time.perf_counter()
r = func(*args, **kwargs)
end = time.perf_counter()
print("{}.{} : {}".format(func.__module__, func.__name__, end - start))
return r
return wrapper
要使用这个装饰器，只要简单地将其放在函数定义之前，就能得到对应函数的计时信息了。示例如下：
@timethis
def countdown(n):
while n > 0:
n -= 1
countdown(10000000)
控制台打印输出：
__main__.countdown : 0.574160792
请注意，在进行性能统计时，任何得到的结果都是近似值。我们这里使用的函数
time.perf_counter()
是能够提供给定平台上精度最高的计时器，它返回一个秒级的时间值。但是，它计算的仍然是挂钟时间（墙上时间），这会受到许多不同因素的影响（例如机器当前的负载），且它会将程序等待中断的sleep（休眠）时间也计算在内。
如果相对于挂钟时间，我们更感兴趣的是进程时间（包括在内核态和用户态中所花费的CPU时间），那么可以使用
time.process_time()
来替代。示例如下：
def timethis(func):
@wraps(func)
def wrapper(*args, **kwargs):
start = time.process_time()
r = func(*args, **kwargs)
end = time.process_time()
print("{}.{} : {}".format(func.__module__, func.__name__, end - start))
return r
return wrapper
接下来我们看如何对语句块进行计算统计，这可以通过定义一个上下文管理器来实现。示例如下：
from contextlib import contextmanager
@contextmanager
def timeblock(label):
start = time.perf_counter()
try:
yield
finally:
end = time.perf_counter()
print("{} : {}". format(label, end - start))
下面这个例子演示了这个上下文管理器是如何工作的：
with timeblock("counting"):
n = 10000000
while n > 0:
n -= 1
控制台打印输出如下所示：
counting : 0.7888195419999999
最后，我们来看一种一劳永逸的方案：在
time
模块中的函数之上构建一个更高层的接口来模拟秒表，从而解决对函数、对代码块的计时问题。
import time
class Timer:
def __init__(self, func=time.perf_counter):
self.elapsed = 0.0
self._func = func
self._start = None
def start(self):
if self._start is not None:
raise RuntimeError("Already started!")
self._start = self._func()
def stop(self):
if self._start is None:
raise RuntimeError("Not started!")
end = self._func()
self.elapsed += end - self._start
self._start = None
def reset(self):
self.elapsed = 0.0
@property
def running(self):
return self._start is not None
def __enter__(self):
self.start()
return self
def __exit__(self, *args):
self.stop()
这个类定义了一个定时器，可以根据用户的需要启动、停止和重置它。
Timer
类将总的花费时间记录在
elapsed
属性中。下面的实例展示了如何使用这个类：
t = Timer()
# Use 1: Explicit start/stop
t.start()
countdown(1000000)
t.stop()
print(t.elapsed)
# 0.058305625
# Use 2: As a context manager
with t:
countdown(1000000)
print(t.elapsed)
# 0.11482683300000004
with Timer() as t2:
countdown(1000000)
print(t2.elapsed)
# 0.056095916999999995
如同前面所展示的，由
Timer
类记录的时间是挂钟时间，其中包含了所有的sleeping时间。如果仅想获取进程的CPU时间（包括在用户态和内核态中的时间），可以用
time.process_time()
取代。示例如下：
t = Timer(time.process_time)
with t:
countdown(1000000)
print(t.elapsed)
# 0.05993699999999999
2.2 分析单条代码片段
如果要对短小的代码片段做性能统计，
timeit
模块会很有帮助。示例如下：
from timeit import timeit
print(timeit("math.sqrt(2)", "import math"))
# 0.07840395799999997
print(timeit("sqrt(2)", "from math import sqrt"))
# 0.05943025000000002
timeit
会执行第一个参数中指定的语句一百万次，然后计算时间。第二个参数是一个配置字符串，在运行测试之前会先执行以设定好环境。如果要修改需要迭代的次数，只需要提供一个number参数即可：
print(timeit("math.sqrt(2)", "import math", number=10000000))
# 0.7569702089999999
print(timeit("sqrt(2)", "from math import sqrt", number=10000000))
# 0.5865757500000002
最后但同样重要的是，如果打算进行详细的计时统计分析，请确保先阅读
time
、
timeit
以及其他相关模块的文档。这样才能理解不同系统平台之间的重要差异以及其他一些缺陷。
