2.4 简单计时方法——print语句和装饰器

前面显示了代码中的一些print语句生成的输出。在作者的笔记本电脑上使用CPython 3.7运行这些代码时，执行时间大约为8 s。请注意，执行时间并非固定不变的，计算代码的执行时间时，必须考虑正常波动，否则可能将执行时间的随机变化归功于对代码所做的改进。

运行代码时，计算机还执行其他任务，如访问网络、磁盘或RAM，而这些因素会导致代码的执行时间发生变化。

作者的笔记本电脑是一台Dell 9550，它配置了Intel Core I7 6700HQ CPU（2.6 GHz、6 MB缓存、双核、支持超线程），内存为32 GB，安装的操作系统为Linux Mint 19.1（Ubuntu 18.04）。

在函数calc_pure_python（示例2-2）中，有几条print语句。这是测量函数中代码执行时间的最简单方式。这种基本方法虽然有些粗糙，但在刚着手研究代码时很有用。

在调试和剖析代码时，print语句是一种常用手段。它虽然难以管理，但对简单的调查很有用。使用完print语句后，务必将其删除，否则输出将乱得一塌糊涂。

一种更整洁的方法是使用装饰器，为此只需在目标函数前面添加一行代码。这里使用的装饰器非常简单，只是重现print语句的效果。稍后，我们可以让代码更高级。

示例2-5定义了新函数timefn，它将另一个函数作为参数。这个新函数定义了函数measure_time，它接收参数*args（数量可变的位置参数）和**kwargs（数量可变的键-值对参数），并将它们传递给函数fn。在调用fn之前和之后，程序都调用了time.time()来记录时间，然后打印结果以及函数名（fn._  _name_ _）。使用这个装饰器的开销很小，但如果调用fn数百万次，开销可就不小了。为向调用者暴露被装饰的函数的名称和文档字符串，我们使用了@wraps(fn)；如果不这样做，暴露的将是装饰器（而不是它装饰的函数）的名称和文档字符串。

示例2-5　定义自动计时的装饰器

from functools import wraps
　
def timefn(fn):
    @wraps(fn)
def measure_time(*args, **kwargs):
        t1 = time.time()
        result = fn(*args, **kwargs)
        t2 = time.time()
print(f"@timefn: {fn._ _name_ _} took {t2 - t1} seconds")
return result
return measure_time
　
@timefn
def calculate_z_serial_purepython(maxiter, zs, cs):
    ...

运行这个版本的代码（它保留了以前的print语句）时，发现其执行速度比从calc_pure_python中调用快些，这是因为函数调用存在开销（差别微乎其微）：

    Length of x: 1000
    Total elements: 1000000
    @timefn:calculate_z_serial_purepython took 8.00485110282898 seconds
    calculate_z_serial_purepython took 8.004898071289062 seconds

注意：添加剖析信息不可避免地会降低执行速度——有些剖析选项提供了大量信息，但会严重影响速度，因此必须在剖析信息的详细程度和速度之间进行权衡。

也可以使用模块timeit来粗略地测量CPU密集型函数的执行速度。更典型的情况是，尝试解决问题的不同方式时，通常使用这个模块来测量各种简单表达式的执行时间。

警告：模块timeit会暂时禁用垃圾收集器。如果受测操作会调用垃圾收集器，那么这可能影响测量结果。有关这方面的帮助信息，请参阅Python文档。

可从命令行运行timeit，如下所示：

python -m timeit -n 5 -r 1 -s "import julia1" \
 "julia1.calc_pure_python(desired_width=1000, max_iterations=300)"

请注意，必须使用设置选项-s来导入calc_pure_python所在的模块。timeit的一些默认设置适合简短的代码，但对于运行时间较长的函数，最好指定循环次数（-n 5）和重复次数（-r 5）。这样，结果将为多次重复的最佳结果。要显示每次重复中所有循环的累计时间，可添加标志-v，这有助于展示结果的波动性。

如果没有指定-n和-r，timeit将默认循环10次并重复5次，对函数calc_pure_python来说，这需要6 min。如果想更快地获得结果，可修改默认设置。

我们只关心最佳结果，因为其他结果可能受到了其他进程的影响：

5 loops, best of 1: 8.45 sec per loop

请尝试运行多次，看看结果是否不同——要获得稳定的最佳结果，可能需要增加重复次数。不存在绝对正确的配置，如果发现计时结果波动很大，就增加重复次数，直到结果相当稳定为止。

上述输出表明，调用calc_pure_python的开销为8.45 s（最佳结果），而前面使用装饰器@timefn调用calculate_z_serial_purepython的开销为8.0 s。区别主要在于创建列表zs和cs所需的时间。

在IPython中，可以用同样的方式使用魔法命令%timeit。在IPython或Jupyter Notebook中以交互方式编写代码时，可像下面这样做：

In [1]: import julia1
In [2]: %timeit julia1.calc_pure_python(desired_width=1000, max_iterations=300)

警告：请注意，在Jupyter和IPython中，魔法命令%timeit计算最佳结果的方式与timeit.py方法不同。timeit.py使用的是最小值（最短时间），而IPython从2016年起转而使用平均值和标准偏差。这两种方法都存在缺陷，但通常都是合理的，虽然它们之间没有可比性。因此，请坚持使用其中的一种方法，而不要混用。

必须考虑计算的负载变化。有很多在后台运行的任务，如Dropbox、备份操作，它们可能随机地占用CPU和磁盘资源。网页中的脚本也会导致不可预测的资源占用。图2-4表明，执行前述某些计时步骤时，有个核心的占用率为100%，而其他核心的占用率都较低。

图2-4　在我们对函数进行计时期间，Ubuntu系统监视器显示的后台任务的CPU占用情况

系统监视器的结果表明，机器中的活动会时不时地出现峰值，因此必须使用系统监视器来核实没有其他进程占用关键资源（CPU、磁盘、网络）。