Debunking a Python Custom Log Decorator

Python decorators are a powerful feature that allows you to modify or enhance functions without directly changing their source code. In this article, we'll break down a custom decorator that logs function execution time, understanding each component and its purpose.

The Complete Example

Let's start with our implementation:

import functools
import logging
from datetime import datetime

def log_execution_time(operation_name: str, logger: logging.Logger = app_logger):
    def decorator(func):
        @functools.wraps(func)
        def wrapper(*args, **kwargs):
            start_time = datetime.now()
            result = func(*args, **kwargs)
            end_time = datetime.now()
            execution_time = end_time - start_time
            logger.info(f"{operation_name} execution time {execution_time}")
            return result
        return wrapper
    return decorator

Breaking Down the Components

1. Decorator Parameters

The outer function log_execution_time accepts parameters that customize the decorator's behavior:

def log_execution_time(operation_name: str, logger: logging.Logger = app_logger):

This allows us to configure the decorator when applying it to a function:

@log_execution_time(operation_name="estimate_pi")
def my_function():
    pass

2. The Decorator Function

def decorator(func):

This function receives the original function (func) as its argument. It's responsible for wrapping the original function with additional functionality.

3. Preserving Function Metadata

@functools.wraps(func)

This crucial decorator preserves the original function's metadata (name, docstring, etc.) which would otherwise be lost in the wrapping process.

For example, without it, the __name__ attribute of the decorated function would be wrapper:

>>> estimate_pi.__name__
'wrapper'

But, with @functools.wraps(func):

>>> estimate_pi.__name__
'estimate_pi'

4. The Wrapper Function

def wrapper(*args, **kwargs):

This innermost function:

Accepts any arguments (*args and **kwargs)
Executes the timing logic
Calls the original function with its arguments
Returns the result

The *args and **kwargs syntax makes the decorator flexible, allowing it to work with any function regardless of its parameters.

Let's break this down with another example:

@log_execution_time(operation_name="my_function")
def my_function(name, age, city="Paris", **extra_info):
    # Function implementation...
    pass

# When you call the function like this:
my_function("Alice", 25, city="London", hobby="reading", job="developer")

Inside the decorator:

def wrapper(*args, **kwargs):
    # Here:
    # args = ("Alice", 25)              # positional arguments
    # kwargs = {                        # keyword arguments
    #     "city": "London",
    #     "hobby": "reading",
    #     "job": "developer"
    # }

    start_time = datetime.now()
    result = func(*args, **kwargs)      # Calls my_function with all original arguments
    end_time = datetime.now()
    # ... rest of the code ...

Usage Example

Here's how to use the decorator:

@log_execution_time(operation_name="estimate_pi")
def estimate_pi(num_points: int = 1000) -> float:
    # Monte Carlo method implementation
    return pi_estimate

# When called:
result = estimate_pi(100000)

Sample output:

2024-11-16 10:44:27,047 - monte_carlo_pi - INFO - estimate_pi execution time 0:00:00.087925

Understanding the Execution Flow

When Python encounters a decorated function:

The decorator factory (log_execution_time) is called with its arguments
It returns the decorator function
The decorator function receives the original function as func
It returns the wrapper function
When the decorated function is called:
The wrapper executes
Times the function
Logs the execution time
Returns the original function's result

Best Practices Demonstrated

Use of functools.wraps: Preserves function metadata
Flexible argument handling: Using *args and **kwargs
Configurable decorator: Accepts parameters for customization
Default parameters: Provides default logger while allowing custom ones
Type hints: Improves code readability and IDE support

Conclusion

This decorator example demonstrates several Python concepts:

Nested functions
Function decoration
Metadata preservation
Flexible argument handling
Logging integration

Understanding these components helps in creating maintainable and reusable decorators for various purposes beyond just logging execution time.

Bonus: other common decorators

@lru_cache: Cache the results of a function
@singledispatch: Dispatch methods based on the type of the first argument
@cache: Cache the results of a function
@retry: Retry a function a certain number of times if it fails
@property: Turn a method into a property
@classmethod: Turn a method into a class method
@staticmethod: Turn a method into a static method
@contextmanager: Turn a generator into a context manager

Source code

python logger decorator example in github repository