Logging Utilities - Usage Guide

Overview

logging_utils.py provides lazy evaluation logging to prevent expensive string formatting (e.g., NumPy array conversion) when the log level is disabled.

Performance Impact

Without lazy evaluation:

# ❌ BAD: Array is converted to string even if DEBUG is disabled
logger.debug(f"Array data: {numpy_array}")  # Slow: formats string every call

With lazy evaluation:

# ✅ GOOD: Array conversion only happens if DEBUG is enabled
lazy_logger.debug(lambda: f"Array data: {numpy_array}")  # Fast: skips formatting

Performance: orders of magnitude faster when log level is disabled.

When to Use Lazy Logging

Use Case	Method	Reason
NumPy arrays	LazyLogger or isEnabledFor	Array to string conversion is expensive
Large objects	LazyLogger or isEnabledFor	repr/str conversion is expensive
Expensive computations	LazyLogger	Skip computation entirely
Simple strings/numbers	Standard logger	No overhead benefit
INFO or higher levels	Standard logger	Usually executed anyway

Usage Examples

Method 1: LazyLogger (Recommended for New Code)

from pybullet_fleet.logging_utils import get_lazy_logger

# Create lazy logger
lazy_logger = get_lazy_logger(__name__)

# Use with lambda for expensive operations
import numpy as np
arr = np.random.rand(1000)

lazy_logger.debug(lambda: f"Array stats: mean={arr.mean()}, std={arr.std()}, data={arr[:10]}")
lazy_logger.info(lambda: f"Large object: {expensive_object}")

# Simple strings work too (lambda is optional but consistent)
lazy_logger.debug(lambda: "Simple message")
lazy_logger.debug("Simple message also works")  # Backward compatible

Method 2: isEnabledFor Check (Good for Existing Code)

def _init_differential_rotation_trajectory(self, goal):
    # These lines caused significant overhead in hot paths!
    logger.debug(f"Agent {self.body_id} checking orientation alignment:")
    logger.debug(f"  Movement direction: {x_axis_target}")  # NumPy array
    logger.debug(f"  Goal's X-axis: {x_axis_goal}")         # NumPy array
    logger.debug(f"  Alignment: {alignment:.3f}")

After optimization (significantly faster):

def _init_differential_rotation_trajectory(self, goal):
    if logger.isEnabledFor(logging.DEBUG):
        logger.debug(f"Agent {self.body_id} checking orientation alignment:")
        logger.debug(f"  Movement direction: {x_axis_target}")
        logger.debug(f"  Goal's X-axis: {x_axis_goal}")
        logger.debug(f"  Alignment: {alignment:.3f}")

API Reference

`get_lazy_logger(name: str) -> LazyLogger`

Create a new lazy logger.

logger = get_lazy_logger(__name__)
logger.debug(lambda: f"Data: {array}")

`wrap_existing_logger(logger: logging.Logger) -> LazyLogger`

Wrap an existing logger with lazy evaluation.

std_logger = logging.getLogger(__name__)
lazy_logger = wrap_existing_logger(std_logger)
lazy_logger.debug(lambda: f"Data: {array}")

`LazyLogger` Methods

All standard logging methods are supported:

debug(msg_func, *args, **kwargs)
info(msg_func, *args, **kwargs)
warning(msg_func, *args, **kwargs)
error(msg_func, *args, **kwargs)
critical(msg_func, *args, **kwargs)

msg_func can be:

A lambda/callable: lambda: f"Data: {array}" (lazy evaluation)
A plain string: "Simple message" (backward compatible)

Testing

Run the test suite to verify functionality and see performance benchmarks:

python PyBulletFleet/tests/test_logging_utils.py

Expected output:

Performance Benchmark (10,000 iterations)
Standard logger:           slow (baseline)
Standard with check:       fast (>99% faster)
Lazy logger:               fast (>99% faster)

Conclusion: Lazy logger is orders of magnitude faster for disabled log levels

Best Practices

✅ DO

# Use lazy logging for arrays and expensive operations
lazy_logger.debug(lambda: f"Array: {np_array}")
lazy_logger.debug(lambda: f"Mean: {data.mean()}")

# Or use isEnabledFor for multiple related logs
if logger.isEnabledFor(logging.DEBUG):
    logger.debug(f"Array 1: {arr1}")
    logger.debug(f"Array 2: {arr2}")

❌ DON’T

# Don't use lazy logging for simple strings (unnecessary overhead)
lazy_logger.debug(lambda: "Simple message")  # Just use: logger.debug("Simple message")

# Don't forget the lambda
lazy_logger.debug(f"Array: {arr}")  # ❌ Still evaluates f-string!
lazy_logger.debug(lambda: f"Array: {arr}")  # ✅ Correct

Performance Tips

Group expensive logs: Use isEnabledFor to wrap multiple related DEBUG logs
Profile first: Use profile_agent_manager_set_goal.py to identify bottlenecks
Focus on hot paths: Optimize logs in frequently-called functions first
Keep it simple: Don’t over-optimize INFO/WARNING/ERROR logs

Migration Checklist

Identify hot paths (frequently called functions)
Search for DEBUG logs with arrays/objects: logger.debug(f".*\{.*\[
Add isEnabledFor checks or use LazyLogger
Run tests to verify functionality
Profile to measure improvement
Update documentation