Python代码性能分析（前篇）

前言

我们怎样知道执行某个Python文件、某个函数、某段代码所耗费的总体时间？这是这篇文章尝试去回答的问题。
作为样例，本文使用slow_func.py来进行性能分析，内容如下：

# coding:utf-8
import time
import random

def func1():
    time.sleep(1)  # 等待一秒

def func2():
    for _ in range(2 ** 24):
        random.random()  # 生成1600万个随机数

if __name__ == '__main__':
    func1()
    func2()

函数func1和func2的区别在于：CPU在执行func1时基本处在闲置状态，在执行func2()时基本处于忙碌状态。这点会在之后的测试中有所体现。
在笔者的测试平台（Ubuntu 18.04+Python 3.6）上，两个函数所耗费的时间均在1s左右。

time命令

类UNIX平台提供了time命令以统计执行执行命令所花费的时间。当然，这是一个通用型的工具，而不局限于Python。
执行如下shell命令：

time python3 slow_func.py

获得如下结果：

real	0m1.960s  # 命令执行时间
user	0m0.946s  # 用户态CPU时间
sys 	0m0.008s

根据前两行结果中我们可以得知，slow_func.py从开始到结束共消耗了2秒左右的时间，但实际消耗的用户态CPU时间只有1秒左右。这是因为CPU在执行func1()时处于等待状态（sleep），这段时间里是不消耗CPU时间的。

time库

Python提供了标准库time来进行关于时间的操作，我们可以通过这个库来测量代码执行所耗费的时间。
执行如下Python代码：

import time
from slow_func import func1, func2

start1, start2 = time.perf_counter(), time.process_time()
func1()
func2()
print('perf_counter: {:.4f}s'.format(time.perf_counter() - start1))
print('process_time: {:.4f}s'.format(time.process_time() - start2))

获得如下结果：

perf_counter: 2.1201s
process_time: 1.1119s

time.perf_counter()的时间差是代码开始与代码结束两个时间点的时间差，而time.process_time()的时间差是消耗的CPU时间长度，所以得出了不同的结果，这与先前的time命令的原因和结果相类似。

time库+上下文管理器

上面提到的用time库来测量代码耗时用起来很方便，但如果经常要用到的话写起来也很繁琐。这时我们可以写一个自定义的上下文管理器来避免重复代码。
执行如下Python代码：

import time
from contextlib import contextmanager

@contextmanager
def time_block(label):  # 代码块计时上下文管理器
    # 进入上下文
    start = time.perf_counter()
    try:
        yield  # 执行代码块
    finally:
        # 执行完成后输出代码块耗时
        used = time.perf_counter() - start
        print('{}: {:.4f}s'.format(label, used))

# 用法
with time_block('sleep'):
    time.sleep(1)

获得如下结果：

sleep: 1.0011s

time库+函数装饰器

上下文管理器针对的是代码块，如果只想统计函数执行所消耗的时间，用函数装饰器更为方便和快捷。
执行如下Python代码：

import time
from functools import wraps

def time_wrap(func):  # 函数计时装饰器
    @wraps(func)
    def wrapper(*args, **kwargs):
        start = time.perf_counter()
        r = func(*args, **kwargs)
        used = time.perf_counter() - start
        print('{f.__module__}.{f.__name__}: {t:.4f}s'.format(f=func, t=used))
        return r

    return wrapper

@time_wrap  # 函数定义时使用装饰器
def slow_func():
    time.sleep(1)

# 执行函数时自动调用装饰器
slow_func()

获得如下结果：

__main__.slow_func: 1.0008s

timeit库

当需要多次重复测量Python代时以获取精确的耗时结果时，我们可以通过循环控制配合上文提到的方法来实现，也可以通过一个更便捷的、适合重复测试的标准库：timeit来实现。
执行如下代码：

import timeit

setup = 'from slow_func import func1'

used = timeit.timeit('func1()', setup=setup, number=5)
print('{:.4f}'.format(used))

获得如下结果：

5.0039

timeit库默认使用的计时器为time.perf_counter()，如果想换成测量CPU耗时的计时器，只需要附加上timer参数即可：

...
import time
timer = time.process_time

used = timeit.timeit('func1()', timer=timer, setup=setup, number=5)  # 附加timer参数
...