Skip to Content
Course content

199: Practice Exercise: Building a Timing and Logging Decorator

Click on the "Edit" button in the top corner of the screen to edit your slide content.

How do I actually capture the execution time without messing up the function call?

The trick is to wrap the original function call between two timestamps. I always recommend using time.perf_counter() rather than time.time() for this. Why? Because perf_counter has a much higher resolution and isn't affected by system clock updates, making it the gold standard for profiling code.

import time

def timer_decorator(func):
    def wrapper(*args, **kwargs):
        start_time = time.perf_counter()
        result = func(*args, **kwargs)  # Execute the actual function
        end_time = time.perf_counter()
        
        duration = end_time - start_time
        print(f"Function {func.__name__} took {duration:.4f} seconds")
        return result
    return wrapper

Notice how I store the result first. If you print the time before returning the result, you're fine, but if you forget to return that result, your decorated function will suddenly start returning None, and you'll spend an hour wondering why your data disappeared.

What's the deal with those star-args and double-star-kwargs?

Since you don't know which function you'll be decorating—it could be a simple function with no arguments or a complex one with ten—you have to make the wrapper "transparent." Using *args and **kwargs allows the decorator to accept any combination of positional and keyword arguments and pass them straight through to the original function.

I've seen a lot of beginners try to define specific arguments in the wrapper, but that defeats the purpose of a decorator. The goal is a "one size fits all" shell. When you call func(*args, **kwargs), Python essentially unpacks those collections back into the original format the function expects.

Why do I keep seeing @functools.wraps in professional code?

If you don't use @wraps, you're essentially replacing your original function with the wrapper function. This means if you try to check my_function.__name__ or look at its docstring, you'll get "wrapper" instead of "my_function." It's a metadata nightmare that can break debugging tools and automated documentation generators.

It's a small addition, but it's the difference between "scripting" and "software engineering." Here is how it fits in:

from functools import wraps
import time

def logger_timer(func):
    @wraps(func) # This preserves the original function's identity
    def wrapper(*args, **kwargs):
        print(f"Now calling: {func.__name__}")
        start = time.perf_counter()
        res = func(*args, **kwargs)
        end = time.perf_counter()
        print(f"Finished {func.__name__} in {end-start:.4f}s")
        return res
    return wrapper

Can I add logging to this instead of just printing to the console?

Absolutely. In a real production environment, print is usually forbidden because it's hard to filter and doesn't provide timestamps or severity levels. You'd swap the print statements for the logging module. This allows you to send these timing logs to a file or a cloud monitoring service without changing the core logic of your decorator.

Imagine decorating a function that fetches data from a slow API. By logging the time and the arguments used, you can pinpoint exactly which API calls are lagging for which users without adding print statements to every single function in your codebase.




📋 Practical Task

Exercise: Build a Performance-Tracking API Simulator

You are tasked with creating a timing and logging decorator to monitor a simulated "slow" system. Follow these requirements:

  • Create a decorator named monitor_performance.
  • The decorator must use functools.wraps to preserve function metadata.
  • Inside the decorator, print a message stating "Executing [function_name]..." before the function runs.
  • Use time.perf_counter() to calculate the elapsed time of the function execution.
  • Print a final message stating "[function_name] completed in [X] seconds."
  • Apply this decorator to two different functions:
    • fetch_user_data(user_id): This function should use time.sleep(0.5) to simulate a database delay and return a dictionary of user info.
    • process_payment(amount, currency="USD"): This function should use time.sleep(1.2) to simulate a payment gateway and return a boolean True.

Run both functions and verify that the timing is captured correctly for both the single-argument and multi-argument functions.

Rating
0 0

There are no comments for now.

to be the first to leave a comment.