Flask中time库返回装饰器函数错误执行时间的问题

项目文件结构 #

src/
    ham.py
    eggs.py
    endpoint.py

代码内容 #

ham.py #

from functools import wraps
import time

def ham1(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
       start_time = time.monotonic()
       i = func(*args, **kwargs)

       time.sleep(2)

       print(f'Execution time | ham1 -- {(time.monotonic() - start_time)} secs')

       return True

    return wrapper

eggs.py #

from functools import wraps
import time

def egg1(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
       i = func(*args, **kwargs)
       start_time = time.monotonic()

       time.sleep(20)

       print(f'Execution time | egg1 -- {(time.monotonic() - start_time)} secs')

       return True
    return wrapper

def egg2(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
       start_time = time.monotonic()
       i = func(*args, **kwargs)

       time.sleep(1)

       return True
       print(f'Execution time | egg2 -- {(time.monotonic() - start_time)} secs')

    return wrapper

def egg3(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
       start_time = time.monotonic()
       i = func(*args, **kwargs)

       time.sleep(1)

       print(f'Execution time | egg3 -- {(time.monotonic() - start_time)} secs')

       return True
    return wrapper

endpoint.py #

from ham import ham1
from eggs import egg1, egg2, egg3

@egg3
@egg2
@egg1
@ham1
def foo():
    return True

执行结果 #

运行foo()后输出：

Execution time | ham1 -- 2 secs
Execution time | egg1 -- 20 secs
Execution time | egg2 -- 21 secs
Execution time | egg3 -- 22 secs

问题 #

egg2和egg3的执行时间显示错误，本应各为1秒，但却累加了egg1的执行时间；而egg1未累加ham.py中ham1的执行时间，该异常仅发生在同一文件eggs.py内的函数中。尝试使用time.perf_counter()后问题依旧，想了解该现象的原因，是否是Flask后台存在异步运行导致？

原因分析与解决方法 #

这和Flask异步运行无关，完全是装饰器的执行顺序和代码逻辑差异导致的：

1. 装饰器执行顺序：Python装饰器遵循从下到上的执行逻辑（最靠近函数的装饰器先执行），调用foo()时的实际执行链路是：egg3.wrapper → egg2.wrapper → egg1.wrapper → ham1.wrapper → foo()。

2. egg1与ham1的特殊逻辑：egg1和ham1都是先调用内层函数，再定义start_time，所以它们的时间计算只包含自身time.sleep的耗时，不会叠加内层装饰器的执行时间。

3. egg2与egg3的逻辑缺陷：

   • egg2和egg3是先定义start_time，再调用内层函数，因此它们的时间计算会包含内层所有装饰器的执行时间（比如egg3的时间会叠加egg2、egg1、ham1以及自身sleep的总耗时）；
   • 另外原代码中egg2的print语句写在return True之后，实际永远不会执行，你看到的egg2输出应该是代码修正后的结果。

4. 同一文件的误解：所谓“同一文件内函数异常”只是巧合，本质是egg2、egg3的代码逻辑和egg1、ham1不一致，和文件归属无关。

修正方案 #

如果要让每个装饰器仅计算自身的执行时间（不包含内层装饰器耗时），需要将start_time的定义移到内层函数执行之后，和egg1、ham1的逻辑保持一致：

修改后的egg2和egg3：

def egg2(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
       i = func(*args, **kwargs)
       start_time = time.monotonic()

       time.sleep(1)

       print(f'Execution time | egg2 -- {(time.monotonic() - start_time)} secs')
       return True

    return wrapper

def egg3(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
       i = func(*args, **kwargs)
       start_time = time.monotonic()

       time.sleep(1)

       print(f'Execution time | egg3 -- {(time.monotonic() - start_time)} secs')
       return True
    return wrapper

修正后运行foo()，输出会变为：

Execution time | ham1 -- 2 secs
Execution time | egg1 -- 20 secs
Execution time | egg2 -- 1 secs
Execution time | egg3 -- 1 secs

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