Python性能分析(1)-短代码片段运行时间

本文最后更新于 2023年2月17日 凌晨

引言

对于大型 Python 项目，可以使用 VizTracer、memray、py-spy 等专业工具详细分析其内存占用、运行耗时、内部调用关系等性能问题。而有时需要对只几百行的短代码片段进行粗略的性能分析——尤其关注其运行时间，使用这些复杂工具带来的 overhead 太大，需要寻求更简单优雅的方式。

本文循序渐进，首先介绍通过标准库中的 timeit 模块实现计时的详细方法；然后编写装饰器来实现优雅便捷地函数耗时计量；最后介绍通过上下文管理器实现同样便捷、且粒度更细的计时方法。附录中详细讨论了 time 模块中几个函数间的差异，弥补部分同类文章中的瑕疵。

sunburst_visualization

标准库 timeit

Python 在标准库中提供了 timeit 模块，用于测量小代码片段的执行时间。可以通过代码中调用、命令行接口两种方式使用。

timeit.Timer 类

timeit 模块的核心是一个名为 timeit.Timer 的类。下面用一个简单的例子来演示如何创建并使用该类的实例，实现计时功能。

需要被计时的代码片段非常简单，用推导式创建一个指定长度的整数列表：

1
2
length = 100
L = [i for i in range(length)]  # 待计时的代码

编写代码，对其计时：

1
2
3
4
5
6
7
8
import timeit

setup = "range_num = 100"
test_code = "L = [i for i in range(range_num)]"  # 用引号包裹代码段，使其成为字符串

t = timeit.Timer(stmt=test_code, setup=setup)
time_cost = t.timeit(number=1000000)
print(time_cost)  # 1.516600207999545

timeit.Timer 在创建实例 t 时接收了 stmt 与 setup 两个参数。其中 stmt 为需要记录运行时间的代码，而 setup 是为运行 stmt 而必须事先执行一次的代码。然后调用了 Timer.timeit() 方法，将 test_code 重复执行一百万次，将耗费的时间（单位为秒）返回。

以上代码可大致等效为 [1]：

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

range_num = 100  # setup 作为“准备工作”，只运行一次

start_time = time.perf_counter()
for _ in range(1000000):
    # stmt 部分的代码被重复执行
    L = [i for i in range(range_num)]
end_time = time.perf_counter()

time_cost = end_time - start_time
print(time_cost)  # 1.5763441319995763

调用 Timer.timeit() 方法时可以传入 number 参数来指定重复执行 stmt 的次数，其默认值为 1000000。这个数值如果太大，可能导致测试太耗费时间，而太小又会导致误差增加。可以使用 autorange() 方法来自动确定：

1
2
3
4
5
6
7
8
import timeit

setup = "range_num = 100"
test_code = "L = [i for i in range(range_num)]"

t = timeit.Timer(test_code, setup)
exec_times, time_cost = t.autorange()
print(exec_times, time_cost)  # 200000 0.3036361769991345

Timer.autorange() 返回一个包含两个元素的元组：前者为实际执行次数，后者为耗时。该方法会尝试逐渐增加执行次数，直到总时间≥0.2秒为止。

重复执行以上代码多次，会发现虽然每次实验中都已经重复运行待计时代码数十万次，但每次实验之间还是有微小差异。针对这种现象，Timer 类还提供了一个 repeat() 方法，用于重复调用 timeit() 进行反复实验：

1
2
3
4
5
6
7
8
9
10
import timeit

setup = "range_num = 100"
test_code = "L = [i for i in range(range_num)]"

t = timeit.Timer(test_code, setup)
time_cost_list = t.repeat(repeat=5, number=200000)  # 相当于重复5次 t.timeit(200000)
print(time_cost_list)
# [0.3122515510003723, 0.31483292399934726,
# 0.31795581500045955, 0.3165283989983436, 0.3126428750001651]

Timer.repeat() 方法接收两个参数，分别为重复调用 timeit() 的 repeat 次数和每次调用 timeit() 时的 number 参数。该方法返回一个列表，存储着这 repeate 次的耗时情况。注意：不建议以结果的平均值作为参考，而更应看中结果中的最小值[2]。

timeit 函数

如果每次都先实例化 Timer 类再调用方法进行计时，稍显繁琐。所以 timeit 模块还封装出了几个实用的函数，可以“一步到位”。

函数 timeit.timeit() 的使用方式与 Timer.timeit() 方法非常相似：

1
2
3
4
5
6
7
import timeit

setup = "range_num = 100"
test_code = "L = [i for i in range(range_num)]"

time_cost = timeit.timeit(test_code, setup, number=200000)
print(time_cost)

查看源码，完整的函数定义与实现为：

1
2
3
4
def timeit(stmt="pass", setup="pass", timer=default_timer,
           number=default_number, globals=None) -> float:
    """Convenience function to create Timer object and call timeit method."""
    return Timer(stmt, setup, timer, globals).timeit(number)

容易看出，timeit.timeit() 的确只是把创建 Timer 实例和调用其 timeit() 方法二次封装而已。

函数 timeit.repeat() 则是对 Timer.repeat() 方法的二次封装，不再赘述。

1
2
3
4
5
6
7
8
import timeit

setup = "range_num = 100"
test_code = "L = [i for i in range(range_num)]"

time_cost_list = timeit.repeat(test_code, setup, repeat=3, number=200000)
print(time_cost_list)
# [0.3106162330004736, 0.3043330469990906, 0.30264337100015837]

解决命名空间问题

在上面的小节中，待计时的代码只是很简单的一行，也容易将前面所有的代码都放入 setup 参数中。而对于比较复杂的情况，譬如计量某个函数的运行时间，就需要处理命名空间的问题了。下面是一个新的例子：

1
2
3
4
5
6
7
8
def test(range_num):
    """只是一个测试函数"""
    L = [i for i in range(range_num)]
    return L

if __name__ == '__main__':
    import timeit
    print(timeit.timeit("test(100)", number=200000))  # 会报错

在这个例子中，希望计量的是函数 test() 运行耗时。但直接运行目前的代码，会报 NameError: name 'test' is not defined 的错误，显然这是因为 timeit.timeit() 内部所在的命名空间与全局命名空间不同导致的。一种很糟糕但确实可行的做法是，将 test() 函数的所有代码作为字符串，作为 setup 参数传入 timeit.timeit()：

1
2
3
4
5
6
7
8
9
10
11
# 糟糕做法
test_func_code = """
def test(range_num):
    L = [i for i in range(range_num)]
    return L
"""

if __name__ == '__main__':
    import timeit

    print(timeit.timeit("test(100)", test_func_code, number=200000))  # 0.3095456290029688

这严重破坏了原有代码的功能，完成测试后也不容易恢复。必须另寻他法。一种做法是使用 import 语句，将待计时的函数导入：

1
2
3
4
5
6
7
8
9
# 解决方法 1
def test(range_num):
    L = [i for i in range(range_num)]
    return L

if __name__ == '__main__':
    import timeit

    print(timeit.timeit("test(100)", setup="from __main__ import test", number=200000))

另一种做法则是利用 globals 参数，将 timeit.timeit() 放到当前的全局命名空间中执行：

1
2
3
4
5
6
7
8
9
# 解决方法 2
def test(range_num):
    L = [i for i in range(range_num)]
    return L

if __name__ == '__main__':
    import timeit

    print(timeit.timeit("test(100)", globals=globals(), number=200000))

命令行接口

除了在 Python 代码内部使用，timeit 还可以通过命令行使用。有了上面的基础，理解这些命令行参数并不困难：

1
python timeit.py [-n N] [-r N] [-s S] [-p] [-u U] [-v] [-h] [--] [statement]
参数 长参数 含义
-n –number 执行 「statement」 多少次。如未指定，则会
-r –repeat 重复计时器的次数（默认为5）
-s –setup 最初要执行一次的语句（默认为 pass）
-p –process 测量进程时间，而不是现实时间。即，使用 time.process_time() 而不是默认的 time.pref_counter()[3]。
-u –unit 指定输出时间的单位，可在 nsec、usec、msec 和 sec中选择
-v –verbose 打印原始计时结果；为更多位数精度重复
-h –help 打印帮助信息并退出
– – 如果 statement 语句以 - 开头，可以在选项和 statement 之间添加 -- 以示分隔

下面是一组使用例子：

1
2
3
4
5
6
7
8
$ python3.10 -m timeit -u nsec -s 'text = "sample string"; char = "g"'  'text.find(char)'
5000000 loops, best of 5: 82.2 nsec per loop

$ python3.10 -m timeit -u nsec -s 'text = "sample string"; char = "g"'  'char in text'
10000000 loops, best of 5: 20.1 nsec per loop

$ python3.11 -m timeit -u nsec -s 'text = "sample string"; char = "g"'  'char in text'
20000000 loops, best of 5: 17.6 nsec per loop

对于第一行调用，setup 参数为 'text = "sample string"; char = "g"'（Python 代码中亦可通过分号 ; 表示换行，所以这里是将原本两行代码写到一行中）；待计时的 statement 语句为 'text.find(char)'；由于未指定 number 和 repeat 参数，所以使用了 autorange() 自动设置每次重复5000000轮、重复5次。而5次实验中最佳的平均耗时为 82.2 纳秒。

第二行的调用实现的功能与第一行相仿，亦为查找字符是否在文本字符串中出现，但改用 in 语法。从计时结果看，比使用字符串的 find() 方法要快得多。这正是意义所在——横向比较可实现相同功能的不同代码段间的耗时差异，寻求更快的方式。

第三行使用目前最新的 Python 3.11 再次测试，可以看到速度有明显的提升。实际上，在相当一部分场景下，3.11 都有很客观的提速，香农计划初见成效。期待未来版本更快更强的 Python。

使用 Decorator 计量函数耗时

装饰器（Decorator）是 Python 中较为高阶的一种语法糖。对于不熟悉的读者[4]，可将函数装饰器简单理解为一种特殊的函数：接收另一个函数（被修饰的函数）作为参数、进行一些操作（修饰）、最终将修饰后的函数作为返回值返回。下面是最简单版本的例子：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
# timeit_decorator_v1.py
import time

def timeit(f):
    
    def wrapper(*args, **kwargs):
        start = time.perf_counter_ns()
        ret = f(*args, **kwargs)
        print(time.perf_counter_ns() - start)
        return ret
    
    return wrapper

@timeit
def my_func(x):
    time.sleep(x)

my_func(1)

可以通过为装饰器添加 iteration 参数的方式，控制函数反复执行的次数，减小误差：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
# timeit_decorator_v2.py
import time

def timeit(iteration):
    def inner(f):
        def wrapper(*args, **kwargs):
            start = time.perf_counter_ns()
            for _ in range(iteration):
                ret = f(*args, **kwargs)
            print(time.perf_counter_ns() - start)
            return ret

        return wrapper

    return inner

if __name__ == "__main__":

    @timeit(100000)
    def my_func(x):
        return x * 2

    my_func(2)

使用 Context Manager 计量代码段耗时

上下文管理器（Context Manager）。下面通过自行编写一个上下文管理器类，来实现粒度更细的代码段计时操作。

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

class Timer:
    def __enter__(self):
        self.start = time.perf_counter_ns()
        self.end = 0

        def elapsed():
            return self.end - self.start

        return elapsed

    def __exit__(self, *args):
        self.end = time.perf_counter_ns()

if __name__ == "__main__":
    with Timer() as timer:
        time.sleep(1)

    print(timer())

附录a：再探 time 模块

Python 标准库中的 time 库 提供了许多关于时间相关的功能。其中 time.time() 函数以尽可能高精度的方式获取 「当前时间」。在待计量的代码片段之前、之后分别调用该函数，将两次的返回值做差，即可粗略计量耗时。这正是目前相当一部分同类文章中的代码实现。而另一部分较老的教程情况更糟糕，使用了 time.clock() 函数获取时间，但这个函数从 Python 3.8 起已被抛弃，现在尝试调用只能获得 AttributeError。

1
2
3
4
5
6
7
8
import time

start = time.time()
time.sleep(1)
end = time.time()

time_cost = end - start
print(time_cost)

然而，time.time() 就是最适合用于计量性能的函数吗？

性能计数器时钟

查看文档或 timeit 源码，容易发现 time 库中的另一个函数：

time.perf_counter() 返回一个性能计数器的值，即用于测量较短持续时间的具有最高有效精度的时钟。它会包括睡眠状态所消耗的时间并且作用于全系统范围。返回值的参考点未被定义，因此只有两次调用之间的差值才是有效的。

显然 time.perf_counter() 正是专为性能分析设计，是比 time.time() 更好的选择。参考 PEP 564 中的数据，perf_counter() 的精度明显优于 time()，再次证实了这一点。

使用_ns函数提高精度

从 3.7 版本开始，time 模块引入了新的 time.perf_counter_ns() 函数。该函数功能上与 time.perf_counter() 非常相似，但返回值为 int 类型（避免了浮点数导致的精度损失），单位为纳秒(ns)。查阅将该函数引入 Python 标准库的 PEP 564 可以看出，在 Linux 和 Windows 平台下，time.perf_counter_ns() 的精度都要高于 time.perf_counter()。再考虑到当前已是2022年末[5]，认为绝大多数用户都已经在使用 3.7 及后续版本，故本文全面使用 time.perf_counter_ns() 函数。

进程耗时与实际耗时

time 模块中还有一个函数 time.process_time()，也是 timeit 模块的备选计时函数，其文档为：

time.process_time() 返回当前进程的系统和用户 CPU 时间的总计值。它不包括睡眠状态所消耗的时间。根据定义它只作用于进程范围。返回值的参考点未被定义，因此只有两次调用之间的差值才是有效的。

与 time.perf_counter() 的描述有些相似，下面通过一个实验对比二者区别：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
import time

def pc():
    start = time.perf_counter()
    time.sleep(1)
    print(time.perf_counter()-start)

def pt():
    start = time.process_time()
    time.sleep(1)
    print(time.process_time()-start)

pc()  # 1.0001309139988734
pt()  # 0.0

就个人理解，time.perf_counter() 函数用于计量在现实中，执行完该部分代码所耗费的实际时间（墙上的挂钟走过的时间）；而 time.process_time() 是从计算机 CPU 的视角考虑，花费在执行该部分代码进程所耗费的时间，sleep 状态下计算机并没有处理代码，也就不计入时间。

参考资料与注释

参考资料

特别鸣谢

灵感来源：

注释

  1. 两段代码计时结果的微小差异可能来自于垃圾回收机制。Timer.timeit()默认关闭垃圾回收，可以通过在setup参数中加入'gc.enable()'以启用。 ↩
  2. 详见官方文档中的备注 ↩
  3. 关于这二者的区别，见本文附录进程耗时与实际耗时 ↩
  4. 推荐一些关于装饰器的教学视频：视频1、视频2 ↩
  5. Python官方已停止对3.6及更早版本的支持，对3.7版本的支持也将于2023年6月停止 ↩
note
#Python
Python性能分析(1)-短代码片段运行时间
https://muzing.top/posts/d7dc9928/
作者
Muzing
发布于
2022年12月30日
更新于
2023年2月17日
许可协议