examples/query_timing_demo.py

"""
Query Timing Demo

This script demonstrates the various query timing features available in the application.
Run this to see examples of how query performance is tracked and logged.
"""

import sys
import os

# Add parent directory to path to import app modules
sys.path.insert(0, os.path.abspath(os.path.join(os.path.dirname(__file__), '..')))

from app.core.timing import timer, timed, QueryTimer
import time
import logging

# Setup basic logging to see the output
logging.basicConfig(
    level=logging.DEBUG,
    format='%(asctime)s %(levelname)s %(name)s %(message)s'
)

logger = logging.getLogger(__name__)


def demo_context_manager():
    """Demonstrate using the timer context manager."""
    print("\n=== Context Manager Timer Demo ===")
    
    with timer("Fast operation"):
        time.sleep(0.1)  # Simulates fast operation
    
    with timer("Medium operation"):
        time.sleep(0.6)  # Simulates medium-speed operation
    
    with timer("Slow operation"):
        time.sleep(1.2)  # Simulates slow operation


@timed("Decorated function execution")
def demo_decorated_function():
    """Demonstrate using the @timed decorator."""
    print("\n=== Decorator Timer Demo ===")
    time.sleep(0.3)
    return "Function completed"


@timed()  # Uses default name (module.function)
def demo_default_name():
    """Demonstrate decorator with default naming."""
    time.sleep(0.2)
    return "Another function"


def demo_manual_timer():
    """Demonstrate using QueryTimer for manual timing."""
    print("\n=== Manual QueryTimer Demo ===")
    
    qt = QueryTimer()
    
    # Fast query
    qt.start("Simulated fast query")
    time.sleep(0.1)
    elapsed = qt.stop()
    print(f"Elapsed time: {elapsed:.3f}s")
    
    # Medium query
    qt.start("Simulated medium query")
    time.sleep(0.7)
    elapsed = qt.stop()
    print(f"Elapsed time: {elapsed:.3f}s")
    
    # Slow query
    qt.start("Simulated slow query")
    time.sleep(1.5)
    elapsed = qt.stop()
    print(f"Elapsed time: {elapsed:.3f}s")


def demo_nested_timing():
    """Demonstrate nested timing operations."""
    print("\n=== Nested Timing Demo ===")
    
    with timer("Outer operation"):
        time.sleep(0.2)
        
        with timer("Inner operation 1"):
            time.sleep(0.3)
        
        with timer("Inner operation 2"):
            time.sleep(0.4)
        
        time.sleep(0.2)


if __name__ == "__main__":
    print("=" * 60)
    print("Query Timing Features Demonstration")
    print("=" * 60)
    
    # Run all demos
    demo_context_manager()
    
    result = demo_decorated_function()
    print(f"Result: {result}")
    
    result = demo_default_name()
    print(f"Result: {result}")
    
    demo_manual_timer()
    
    demo_nested_timing()
    
    print("\n" + "=" * 60)
    print("Demo Complete!")
    print("=" * 60)
    print("\nLog Legend:")
    print("  DEBUG   = Fast operations (< 500ms)")
    print("  INFO    = Medium operations (500ms - 1s)")
    print("  WARNING = Slow operations (> 1s)")
    print("\nNote: Actual database queries are timed automatically")
    print("via SQLAlchemy event listeners when the app is running.")