Time library returns incorrect execution time for decorator functions in Flask

Question

Say I have the following python files in my src directory for my Flask application (Flask-smortest to be specific):

src/
    ham.py
    eggs.py
    endpoint.py

ham.py has 1 decorator function, while eggs.py has 3 decorator functions

#ham.py script

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 script

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 script

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

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

Upon executing foo() in my flask-smortest application it gives me the following output:

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

The output displays the wrong execution time for func egg2 and func egg3. Its supposed to be 1 second each but for some reason its accumulating the execution time for func egg1. Another thing to note is that func egg1 does not accumulate the execution time for func ham1 which is sitting in a different python file - ham.py . This behavior only happens in functions existing in the same python file - eggs.py.

I tried time.perf_counter() as well but the still the same issue. I don't understand why the app is behaving this way. Is there some asynchronous running happening in the background in flask?

Answer 1

If you're trying to measure total time then what you did on egg is correct, but wrong for ham.

But if time measuring is only intended for decorator-specific operations excluding decoration target's execution time - you must not put target function execution between time measurements.

So either:

# assuming return value of func() is needed
def egg(func):
    def wrapper(*args, **kwargs):
        result = func()  # <---

        start_time = time.monotonic()
        time.sleep(2)
        print(f"{(time.monotonic() - start_time)} secs")
        
        return result
    return wrapper

or this:

def egg(func):
    def wrapper(*args, **kwargs):
        start_time = time.monotonic()
        time.sleep(2)
        print(f"{(time.monotonic() - start_time)} secs")
        
        return func()  # <---
    return wrapper

should be done instead, not inbetween.

---

Such issue can be quickly identified with tons more prints.

import time


def ham(func):
    def wrapper():
        print("[Deco:ham] measuring start time")
        start_time = time.monotonic()

        print("[Deco:ham] running func")
        func()

        print("[Deco:ham] sleeping for 5 secs")
        time.sleep(5)

        print(f"[Deco:ham] sleep done in {(time.monotonic() - start_time)} secs")

    return wrapper


def egg(func):
    def wrapper():
        print("[Deco:egg] running func")
        func()

        print("[Deco:egg] measuring start time")
        start_time = time.monotonic()

        print("[Deco:egg] sleeping for 2 secs")
        time.sleep(2)

        print(f"[Deco:egg] sleep done in {(time.monotonic() - start_time)} secs")

    return wrapper


@egg
@ham
def foo():
    print("[foo] In foo")
    return


if __name__ == '__main__':
    foo()

[Deco:egg] measuring start time
[Deco:egg] running func
[Deco:ham] measuring start time
[Deco:ham] running func
[foo] In foo
[Deco:ham] sleeping for 5 secs
[Deco:ham] sleep done in 5.0 secs
[Deco:egg] sleeping for 2 secs
[Deco:egg] sleep done in 7.0 secs

---

Bonus: contextlib.contextmanager

You can use contextlib.contextmanager (or asynccontextmanager for async variant) for simplifying time measuring and such:

from contextlib import contextmanager

@contextmanager
def measure_time(name: str):
    print(f"[{name}] Start measuring time")
    start_time = time.monotonic()
    yield
    print(f"[{name}] Time taken: {time.monotonic() - start_time} secs")

...

with measure_time("name"):
    ...

full code:

import time
from contextlib import contextmanager


@contextmanager
def measure_time(name: str):
    print(f"[{name}] Start measuring time")
    start_time = time.monotonic()
    yield
    print(f"[{name}] Time taken: {time.monotonic() - start_time} secs")


def ham(func):
    def wrapper():
        func()

        with measure_time("Deco:ham"):
            time.sleep(5)

    return wrapper


def egg(func):
    def wrapper():
        func()

        with measure_time("Deco:egg"):
            time.sleep(3)

    return wrapper


@egg
@ham
def foo():
    print("[foo] In foo")
    return


if __name__ == '__main__':
    foo()

[foo] In foo
[Deco:ham] Start measuring time
[Deco:ham] Time taken: 5.0 secs
[Deco:egg] Start measuring time
[Deco:egg] Time taken: 3.0 secs