I have two functions func1 and func2 on which I'm applying a basic timer decorator @time_elapsed. The problem is that func1 is called within func2 which cause the print of its timing too.
How can I structure my code to apply the decorator only once to func2 while still allowing func1 to be called independently (with a decorator of course)?
Here is my code:
import time
from functools import wraps
def time_elapsed(func):
@wraps(func)
def wrapper(*args, **kwargs):
start_time = time.time()
result = func(*args, **kwargs)
elapsed_time = time.time() - start_time
print(f'{func.__name__} took {elapsed_time:.2f} seconds.')
return result
return wrapper
@time_elapsed
def func1():
time.sleep(2)
@time_elapsed
def func2():
func1()
time.sleep(3)
Current behaviour :
func1()
# func1 took 2.01 seconds.
func2()
# func1 took 2.00 seconds.
# func2 took 5.01 seconds.
Desired behaviour :
func1()
# func1 took 2.01 seconds.
func2()
# func2 took 5.01 seconds.
You can handle this without changing your func* calls, by using a counter to keep track of when the decorator has been invoked.
import time
from functools import wraps
def time_elapsed(func):
# The depth of the nested function calls to be timed and printed
DEPTH = 1
# Set the counter to 0 by default, if it hasn't been set yet
time_elapsed._timer_running = 0
@wraps(func)
def wrapper(*args, **kwargs):
# If the counter is >= the depth, call the function without timing it
if time_elapsed._timer_running >= DEPTH:
return func(*args, **kwargs)
# Getting here means that the counter is less than depth. So we need to
# increment the counter by 1.
time_elapsed._timer_running += 1
# Run the timer stuff just like before
start_time = time.time()
result = func(*args, **kwargs)
elapsed_time = time.time() - start_time
print(f'{func.__name__} took {elapsed_time:.2f} seconds.')
# Cleanup the counter by decrementing it back down by 1
time_elapsed._timer_running -= 1
return result
return wrapper
@time_elapsed
def func1():
time.sleep(0.1)
@time_elapsed
def func2():
func1()
time.sleep(0.2)
@time_elapsed
def func3():
func1()
func2()
time.sleep(0.3)
@time_elapsed
def func4():
func1()
func2()
func3()
time.sleep(0.4)
if __name__ == "__main__":
func1()
print("---")
func2()
print("---")
func3()
print("---")
func4()
When I run this, none of the nested print statements are shown:
$ python double_decorator.py
func1 took 0.11 seconds.
---
func2 took 0.31 seconds.
---
func3 took 0.72 seconds.
---
func4 took 1.54 seconds.
What's cool about this solution is that you can increase the DEPTH if you want to see the some of the inner calls to a degree. For example, here's what shows when I change it to DEPTH = 2:
func1 took 0.11 seconds.
---
func1 took 0.11 seconds.
func2 took 0.31 seconds.
---
func1 took 0.10 seconds.
func2 took 0.31 seconds.
func3 took 0.72 seconds.
---
func1 took 0.11 seconds.
func2 took 0.31 seconds.
func3 took 0.72 seconds.
func4 took 1.54 seconds.
Only the outer function and its first child are printed. The calls from func* doubly and triply nested in the func4 call don't get timed, because the counter is >= the depth.