为何Python装饰器输出耗时4秒，实际运行时间却更短？

问题描述 #

我编写了一个用于测量函数耗时（秒级）的简单装饰器，代码如下：

from functools import wraps
from time import time

def time_it(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        start_time = time()
        res = func(*args, **kwargs)
        print("Time: ", time() - start_time)
        return res
    return wrapper


@time_it
def cycle():
    res = 0
    for i in range(1000):
        res += i
    return res


cycle()

运行代码后输出Time: 4.4，但函数实际运行速度远快于4秒。随后使用time工具验证，执行命令time python 0_decorators/decorator.py后，得到输出Time: 4.38690185546875e-05，且time工具统计显示总耗时为0.059s。使用Python3.11和MacOS 12系统，为何装饰器输出的耗时为4秒，但实际运行时间却更短？

原因分析 #

• 运行环境差异：第一次运行可能是在IDE的调试模式下，IDE会添加变量追踪、断点检测等调试监控操作，这些额外逻辑会大幅增加函数执行耗时。而终端通过time命令直接运行时，是Python纯运行环境，无调试开销，耗时恢复正常。

• 系统负载波动：第一次运行时系统可能处于高负载状态（后台有大量进程占用CPU、内存），导致cycle函数的执行被系统调度延迟，从而拉长了耗时。第二次运行时系统负载降低，函数得以快速执行。

• 终端输出混淆（低概率）：若终端未清空之前的输出，可能误将其他程序的输出当成本次装饰器的结果，但这种情况可能性较低。

验证建议 #

• 关闭IDE调试模式，以普通“运行”模式启动代码，对比耗时是否与终端运行一致。
• 多次在终端执行time python 0_decorators/decorator.py，观察耗时是否稳定在极小值区间，排除系统负载的偶然影响。

内容的提问来源于stack exchange，提问作者mascai