feat: Add comprehensive debug logging for performance diagnosis

- New debug_logger.py with timing and stack trace capabilities
- Tray icon now logs all interactions with millisecond timing
- Main app startup is fully instrumented
- EU focus detection logs and warns if slow (>100ms)
- Menu interactions use QTimer.singleShot to avoid blocking
- Log file saved to Documents/Entropia Universe/Logs/

This will help identify the source of UI slowness (2s menu delay, 7s click delay)
This commit is contained in:
LemonNexus 2026-02-15 23:59:00 +00:00
parent ae281c7bf3
commit 3c8cf641a6
3 changed files with 350 additions and 23 deletions

141
core/debug_logger.py Normal file
View File

@ -0,0 +1,141 @@
"""
EU-Utility - Debug Logger
Comprehensive debug logging with timing measurements for performance diagnosis.
"""
import time
import functools
import traceback
from typing import Optional, Callable, Any
from pathlib import Path
from datetime import datetime
class DebugLogger:
"""Debug logger with timing and performance tracking."""
_instance = None
def __new__(cls):
if cls._instance is None:
cls._instance = super().__new__(cls)
cls._instance._initialized = False
return cls._instance
def __init__(self):
if self._initialized:
return
self._initialized = True
self.enabled = True
self.log_file = None
self.start_times = {}
# Create log file
log_dir = Path.home() / "Documents" / "Entropia Universe" / "Logs"
log_dir.mkdir(parents=True, exist_ok=True)
self.log_file = log_dir / f"eu-utility-debug-{datetime.now().strftime('%Y%m%d-%H%M%S')}.log"
self._log("=" * 80)
self._log("EU-Utility Debug Log Started")
self._log(f"Log file: {self.log_file}")
self._log("=" * 80)
def _log(self, message: str):
"""Write log message to file and console."""
timestamp = datetime.now().strftime("%H:%M:%S.%f")[:-3]
line = f"[{timestamp}] {message}"
# Always print to console
print(line)
# Write to file
if self.log_file:
try:
with open(self.log_file, 'a', encoding='utf-8') as f:
f.write(line + "\n")
except Exception as e:
print(f"[DebugLogger] Failed to write to log: {e}")
def debug(self, component: str, message: str):
"""Log debug message."""
if self.enabled:
self._log(f"[DEBUG][{component}] {message}")
def info(self, component: str, message: str):
"""Log info message."""
self._log(f"[INFO][{component}] {message}")
def warn(self, component: str, message: str):
"""Log warning message."""
self._log(f"[WARN][{component}] {message}")
def error(self, component: str, message: str, exc_info: bool = True):
"""Log error message."""
self._log(f"[ERROR][{component}] {message}")
if exc_info:
self._log(traceback.format_exc())
def start_timer(self, name: str):
"""Start timing an operation."""
self.start_times[name] = time.perf_counter()
self._log(f"[TIMER][START] {name}")
def end_timer(self, name: str) -> float:
"""End timing an operation and log duration."""
if name not in self.start_times:
self._log(f"[TIMER][ERROR] No start time for: {name}")
return 0.0
elapsed = (time.perf_counter() - self.start_times[name]) * 1000
self._log(f"[TIMER][END] {name}: {elapsed:.2f}ms")
del self.start_times[name]
return elapsed
def log_stack(self, component: str, message: str = ""):
"""Log current call stack for debugging."""
self._log(f"[STACK][{component}] {message}")
stack = traceback.format_stack()[:-1] # Exclude this call
for line in stack[-5:]: # Last 5 frames
self._log(f" {line.strip()}")
# Global instance
debug_logger = DebugLogger()
def timed(component: str, operation: Optional[str] = None):
"""Decorator to time function execution."""
def decorator(func: Callable) -> Callable:
@functools.wraps(func)
def wrapper(*args, **kwargs) -> Any:
op_name = operation or func.__name__
timer_name = f"{component}.{op_name}"
debug_logger.start_timer(timer_name)
try:
result = func(*args, **kwargs)
return result
finally:
debug_logger.end_timer(timer_name)
return wrapper
return decorator
def log_call(component: str):
"""Decorator to log function calls."""
def decorator(func: Callable) -> Callable:
@functools.wraps(func)
def wrapper(*args, **kwargs) -> Any:
debug_logger.debug(component, f"CALL {func.__name__}()")
try:
result = func(*args, **kwargs)
debug_logger.debug(component, f"RETURN {func.__name__}()")
return result
except Exception as e:
debug_logger.error(component, f"EXCEPTION in {func.__name__}: {e}")
raise
return wrapper
return decorator

View File

@ -6,6 +6,7 @@ Launch the overlay, floating icon, dashboard, and plugin system.
import sys
import os
import time
from pathlib import Path
# Add project root to path
@ -13,12 +14,20 @@ project_root = Path(__file__).parent.parent
if str(project_root) not in sys.path:
sys.path.insert(0, str(project_root))
# Import debug logger FIRST (before anything else)
from core.debug_logger import debug_logger, timed, log_call
debug_logger.info("MAIN", "Starting EU-Utility...")
start_time = time.perf_counter()
try:
from PyQt6.QtWidgets import QApplication
from PyQt6.QtCore import Qt, QObject, pyqtSignal
PYQT_AVAILABLE = True
except ImportError:
debug_logger.info("MAIN", "PyQt6 imported successfully")
except ImportError as e:
PYQT_AVAILABLE = False
debug_logger.error("MAIN", f"PyQt6 import failed: {e}")
print("Error: PyQt6 is required.")
print("Install with: pip install PyQt6")
sys.exit(1)
@ -26,11 +35,15 @@ except ImportError:
try:
import keyboard
KEYBOARD_AVAILABLE = True
debug_logger.info("MAIN", "keyboard library imported")
except ImportError:
KEYBOARD_AVAILABLE = False
debug_logger.warn("MAIN", "keyboard library not available")
print("Warning: 'keyboard' library not installed.")
print("Global hotkeys won't work. Install with: pip install keyboard")
debug_logger.start_timer("imports")
from core.plugin_manager import PluginManager
from core.perfect_ux import create_perfect_window
from core.tray_icon import TrayIcon
@ -48,6 +61,8 @@ from core.event_bus import get_event_bus
from core.tasks import get_task_manager
from core.audio import get_audio_manager
from core.clipboard import get_clipboard_manager
debug_logger.end_timer("imports")
from core.data_store import get_data_store
@ -73,65 +88,85 @@ class EUUtilityApp:
def run(self):
"""Start the application."""
debug_logger.start_timer("MAIN_run_total")
# Create Qt Application
debug_logger.start_timer("MAIN_create_app")
self.app = QApplication(sys.argv)
self.app.setQuitOnLastWindowClosed(False)
debug_logger.end_timer("MAIN_create_app")
# Enable high DPI scaling (Qt6 has this enabled by default)
# This block is kept for backwards compatibility with Qt5 if ever needed
if hasattr(Qt, 'AA_EnableHighDpiScaling'):
# In Qt6, this attribute is deprecated and always enabled
# The check prevents warnings on Qt6 while maintaining Qt5 compatibility
try:
self.app.setAttribute(Qt.ApplicationAttribute.AA_EnableHighDpiScaling)
except (AttributeError, TypeError):
pass # Qt6+ doesn't need this
pass
# Initialize Plugin API
debug_logger.start_timer("MAIN_init_api")
print("Initializing Plugin API...")
self.api = get_api()
self._setup_api_services()
debug_logger.end_timer("MAIN_init_api")
# Initialize Event Bus
debug_logger.start_timer("MAIN_init_eventbus")
print("Initializing Event Bus...")
self.event_bus = get_event_bus()
self._print_event_bus_stats()
debug_logger.end_timer("MAIN_init_eventbus")
# Initialize Notification Manager
debug_logger.start_timer("MAIN_init_notifications")
print("Initializing Notification Manager...")
self.notification_manager = get_notification_manager()
self.notification_manager.initialize(self.app)
self.api.register_notification_service(self.notification_manager)
print("[Core] Notification service registered")
debug_logger.end_timer("MAIN_init_notifications")
# Load settings
debug_logger.start_timer("MAIN_load_settings")
self.settings = get_settings()
debug_logger.end_timer("MAIN_load_settings")
# Create hotkey handler (must be in main thread)
debug_logger.start_timer("MAIN_init_hotkeys")
self.hotkey_handler = HotkeyHandler()
debug_logger.end_timer("MAIN_init_hotkeys")
# Initialize plugin manager
debug_logger.start_timer("MAIN_load_plugins")
print("Loading plugins...")
self.plugin_manager = PluginManager(None)
self.plugin_manager.load_all_plugins()
debug_logger.end_timer("MAIN_load_plugins")
# Create overlay manager
debug_logger.start_timer("MAIN_init_overlay_mgr")
self.overlay_manager = OverlayManager(self.app)
debug_logger.end_timer("MAIN_init_overlay_mgr")
# Create perfect UX main window
debug_logger.start_timer("MAIN_create_window")
print("Creating main window with perfect UX...")
self.dashboard = create_perfect_window(self.plugin_manager)
self.plugin_manager.overlay = self.dashboard
self.dashboard.show()
debug_logger.end_timer("MAIN_create_window")
# Create system tray icon (replaces floating icon)
debug_logger.start_timer("MAIN_create_tray")
print("Creating system tray icon...")
self.tray_icon = TrayIcon(self.app)
self.tray_icon.show_dashboard.connect(self._toggle_overlay)
self.tray_icon.toggle_activity_bar.connect(self._toggle_activity_bar)
self.tray_icon.quit_app.connect(self.quit)
debug_logger.end_timer("MAIN_create_tray")
# Create Activity Bar (in-game overlay) - hidden by default
debug_logger.start_timer("MAIN_create_activitybar")
print("Creating Activity Bar...")
try:
from core.activity_bar import get_activity_bar
@ -151,15 +186,24 @@ class EUUtilityApp:
except Exception as e:
print(f"[Core] Failed to create Activity Bar: {e}")
self.activity_bar = None
debug_logger.end_timer("MAIN_create_activitybar")
# Connect hotkey signals
self.hotkey_handler.toggle_signal.connect(self._on_toggle_signal)
# Setup global hotkeys
debug_logger.start_timer("MAIN_setup_hotkeys")
self._setup_hotkeys()
debug_logger.end_timer("MAIN_setup_hotkeys")
# Load saved overlay widgets
debug_logger.start_timer("MAIN_load_widgets")
self._load_overlay_widgets()
debug_logger.end_timer("MAIN_load_widgets")
# Log total startup time
total_startup = debug_logger.end_timer("MAIN_run_total")
debug_logger.info("MAIN", f"=== TOTAL STARTUP TIME: {total_startup:.2f}ms ===")
print("EU-Utility started!")
print("Dashboard window is open")
@ -172,6 +216,7 @@ class EUUtilityApp:
self._print_event_bus_stats()
# Run
debug_logger.info("MAIN", "Starting Qt event loop...")
return self.app.exec()
def _setup_api_services(self):
@ -369,56 +414,92 @@ class EUUtilityApp:
def _toggle_overlay(self):
"""Toggle dashboard visibility."""
debug_logger.start_timer("MAIN_toggle_overlay")
debug_logger.debug("MAIN", f"_toggle_overlay called, dashboard exists: {self.dashboard is not None}")
if self.dashboard:
if self.dashboard.isVisible():
debug_logger.debug("MAIN", "Hiding dashboard...")
self.dashboard.hide()
debug_logger.debug("MAIN", "Dashboard hidden")
else:
debug_logger.debug("MAIN", "Showing dashboard...")
self.dashboard.show()
debug_logger.debug("MAIN", "Dashboard shown, calling raise_...")
self.dashboard.raise_()
debug_logger.debug("MAIN", "Calling activateWindow...")
self.dashboard.activateWindow()
debug_logger.debug("MAIN", "Dashboard activation complete")
else:
debug_logger.warn("MAIN", "Dashboard is None!")
debug_logger.end_timer("MAIN_toggle_overlay")
def _toggle_activity_bar(self):
"""Toggle activity bar visibility."""
debug_logger.start_timer("MAIN_toggle_activity_bar")
debug_logger.debug("MAIN", f"_toggle_activity_bar called, activity_bar exists: {hasattr(self, 'activity_bar')}")
if hasattr(self, 'activity_bar') and self.activity_bar:
try:
if self.activity_bar.isVisible():
debug_logger.debug("MAIN", "Hiding activity bar...")
self.activity_bar.hide()
if hasattr(self, 'tray_icon') and self.tray_icon:
self.tray_icon.set_activity_bar_checked(False)
debug_logger.debug("MAIN", "Activity bar hidden")
else:
debug_logger.debug("MAIN", "Showing activity bar...")
self.activity_bar.show()
if hasattr(self, 'tray_icon') and self.tray_icon:
self.tray_icon.set_activity_bar_checked(True)
debug_logger.debug("MAIN", "Activity bar shown")
except Exception as e:
print(f"[Main] Error toggling activity bar: {e}")
debug_logger.error("MAIN", f"Error toggling activity bar: {e}")
else:
print("[Main] Activity Bar not available")
debug_logger.warn("MAIN", "Activity Bar not available")
debug_logger.end_timer("MAIN_toggle_activity_bar")
def _start_eu_focus_detection(self):
"""Start timer to detect EU window focus and show/hide activity bar."""
from PyQt6.QtCore import QTimer
self.eu_focus_timer = QTimer(self.app) # Use app as parent, not self
debug_logger.info("MAIN", "Starting EU focus detection...")
debug_logger.start_timer("MAIN_start_eu_focus")
self.eu_focus_timer = QTimer(self.app)
self.eu_focus_timer.timeout.connect(self._check_eu_focus)
self.eu_focus_timer.start(2000) # Check every 2 seconds (was 500ms - too frequent)
self.eu_focus_timer.start(5000) # Check every 5 seconds (reduced from 2s for debugging)
self._last_eu_focused = False
print("[Core] EU focus detection started")
debug_logger.end_timer("MAIN_start_eu_focus")
debug_logger.info("MAIN", "EU focus detection started (5s interval)")
def _check_eu_focus(self):
"""Check if EU window is focused and show/hide activity bar."""
debug_logger.start_timer("MAIN_check_eu_focus")
try:
if not hasattr(self, 'activity_bar') or not self.activity_bar:
debug_logger.debug("MAIN", "No activity bar, skipping focus check")
return
if not hasattr(self, 'window_manager') or not self.window_manager:
debug_logger.debug("MAIN", "No window manager, skipping focus check")
return
if not self.window_manager.is_available():
debug_logger.debug("MAIN", "Window manager not available, skipping")
return
debug_logger.debug("MAIN", "Finding EU window...")
eu_window = self.window_manager.find_eu_window()
if eu_window:
debug_logger.debug("MAIN", "EU window found, checking focus...")
is_focused = eu_window.is_focused()
debug_logger.debug("MAIN", f"EU focused: {is_focused}, last: {getattr(self, '_last_eu_focused', None)}")
if is_focused != getattr(self, '_last_eu_focused', False):
self._last_eu_focused = is_focused
@ -427,25 +508,33 @@ class EUUtilityApp:
# EU just got focused - show activity bar
if not self.activity_bar.isVisible():
try:
debug_logger.debug("MAIN", "Showing activity bar (EU focused)")
self.activity_bar.show()
if hasattr(self, 'tray_icon') and self.tray_icon:
self.tray_icon.set_activity_bar_checked(True)
print("[Core] EU focused - Activity Bar shown")
debug_logger.info("MAIN", "EU focused - Activity Bar shown")
except Exception as e:
print(f"[Core] Error showing activity bar: {e}")
debug_logger.error("MAIN", f"Error showing activity bar: {e}")
else:
# EU lost focus - hide activity bar
if self.activity_bar.isVisible():
try:
debug_logger.debug("MAIN", "Hiding activity bar (EU unfocused)")
self.activity_bar.hide()
if hasattr(self, 'tray_icon') and self.tray_icon:
self.tray_icon.set_activity_bar_checked(False)
print("[Core] EU unfocused - Activity Bar hidden")
debug_logger.info("MAIN", "EU unfocused - Activity Bar hidden")
except Exception as e:
print(f"[Core] Error hiding activity bar: {e}")
debug_logger.error("MAIN", f"Error hiding activity bar: {e}")
else:
debug_logger.debug("MAIN", "EU window not found")
except Exception as e:
# Silently ignore errors (EU window might not exist)
pass
debug_logger.error("MAIN", f"Error in EU focus check: {e}")
elapsed = debug_logger.end_timer("MAIN_check_eu_focus")
if elapsed > 100: # Log if taking more than 100ms
debug_logger.warn("MAIN", f"EU focus check took {elapsed:.2f}ms - SLOW!")
def _load_overlay_widgets(self):
"""Load saved overlay widgets."""

View File

@ -1,13 +1,29 @@
"""
EU-Utility - System Tray Icon (Simplified)
==========================================
EU-Utility - System Tray Icon (Debug Version)
=============================================
Simple, responsive system tray icon.
Simple, responsive system tray icon with debug logging.
"""
from PyQt6.QtWidgets import QSystemTrayIcon, QMenu, QApplication, QWidget
from PyQt6.QtGui import QAction, QIcon, QColor, QPainter, QFont, QPixmap
from PyQt6.QtCore import pyqtSignal, Qt
from PyQt6.QtCore import pyqtSignal, Qt, QTimer
# Import debug logger
try:
from core.debug_logger import debug_logger
DEBUG_AVAILABLE = True
except ImportError:
DEBUG_AVAILABLE = False
# Dummy logger
class DummyLogger:
def debug(self, *args): pass
def info(self, *args): pass
def warn(self, *args): pass
def error(self, *args): pass
def start_timer(self, *args): pass
def end_timer(self, *args): return 0.0
debug_logger = DummyLogger()
class TrayIcon(QWidget):
@ -19,20 +35,30 @@ class TrayIcon(QWidget):
quit_app = pyqtSignal()
def __init__(self, app: QApplication, parent=None):
debug_logger.start_timer("TrayIcon.__init__")
super().__init__(parent)
self.app = app
debug_logger.debug("TRAY", "Creating tray icon...")
# Create icon
self._create_icon()
# Create menu (but don't set it yet)
debug_logger.debug("TRAY", "Creating menu...")
self._create_menu()
# Connect signals
debug_logger.debug("TRAY", "Connecting signals...")
self.tray_icon.activated.connect(self._on_activated)
debug_logger.end_timer("TrayIcon.__init__")
debug_logger.info("TRAY", "Tray icon initialized")
def _create_icon(self):
"""Create tray icon."""
debug_logger.start_timer("TrayIcon._create_icon")
# Create simple icon
px = QPixmap(64, 64)
px.fill(QColor(255, 140, 66)) # Orange
@ -49,36 +75,104 @@ class TrayIcon(QWidget):
self.tray_icon.setToolTip("EU-Utility")
self.tray_icon.show()
debug_logger.end_timer("TrayIcon._create_icon")
def _create_menu(self):
"""Create simple context menu."""
debug_logger.start_timer("TrayIcon._create_menu")
self.menu = QMenu()
# Track menu timing
self.menu.aboutToShow.connect(self._on_menu_about_to_show)
self.menu.aboutToHide.connect(self._on_menu_about_to_hide)
# Simple actions (no emojis to avoid encoding issues)
debug_logger.debug("TRAY", "Creating Dashboard action...")
self.dashboard_action = QAction("Dashboard", self)
self.dashboard_action.triggered.connect(self.show_dashboard.emit)
self.dashboard_action.triggered.connect(self._on_dashboard_clicked)
self.menu.addAction(self.dashboard_action)
debug_logger.debug("TRAY", "Creating Activity Bar action...")
self.activity_bar_action = QAction("Activity Bar", self)
self.activity_bar_action.setCheckable(True)
self.activity_bar_action.triggered.connect(self.toggle_activity_bar.emit)
self.activity_bar_action.triggered.connect(self._on_activity_bar_clicked)
self.menu.addAction(self.activity_bar_action)
self.menu.addSeparator()
debug_logger.debug("TRAY", "Creating Quit action...")
self.quit_action = QAction("Quit", self)
self.quit_action.triggered.connect(self.quit_app.emit)
self.quit_action.triggered.connect(self._on_quit_clicked)
self.menu.addAction(self.quit_action)
# Set context menu
debug_logger.debug("TRAY", "Setting context menu...")
self.tray_icon.setContextMenu(self.menu)
debug_logger.end_timer("TrayIcon._create_menu")
def _on_menu_about_to_show(self):
"""Called when menu is about to show."""
debug_logger.start_timer("TRAY_MENU_SHOW")
debug_logger.debug("TRAY", "Menu about to show")
def _on_menu_about_to_hide(self):
"""Called when menu is about to hide."""
elapsed = debug_logger.end_timer("TRAY_MENU_SHOW")
debug_logger.debug("TRAY", f"Menu was visible for {elapsed:.2f}ms")
def _on_dashboard_clicked(self):
"""Handle dashboard click with timing."""
debug_logger.start_timer("TRAY_DASHBOARD_CLICK")
debug_logger.debug("TRAY", "Dashboard clicked - emitting signal...")
# Use single shot to not block menu
QTimer.singleShot(0, self._emit_dashboard)
def _emit_dashboard(self):
"""Emit dashboard signal."""
debug_logger.debug("TRAY", "Emitting show_dashboard signal...")
self.show_dashboard.emit()
debug_logger.end_timer("TRAY_DASHBOARD_CLICK")
def _on_activity_bar_clicked(self):
"""Handle activity bar click with timing."""
debug_logger.start_timer("TRAY_ACTIVITYBAR_CLICK")
debug_logger.debug("TRAY", "Activity Bar clicked - emitting signal...")
# Use single shot to not block menu
QTimer.singleShot(0, self._emit_activity_bar)
def _emit_activity_bar(self):
"""Emit activity bar signal."""
debug_logger.debug("TRAY", "Emitting toggle_activity_bar signal...")
self.toggle_activity_bar.emit()
debug_logger.end_timer("TRAY_ACTIVITYBAR_CLICK")
def _on_quit_clicked(self):
"""Handle quit click with timing."""
debug_logger.start_timer("TRAY_QUIT_CLICK")
debug_logger.debug("TRAY", "Quit clicked - emitting signal...")
# Use single shot to not block menu
QTimer.singleShot(0, self._emit_quit)
def _emit_quit(self):
"""Emit quit signal."""
debug_logger.debug("TRAY", "Emitting quit_app signal...")
self.quit_app.emit()
debug_logger.end_timer("TRAY_QUIT_CLICK")
def show(self):
"""Show the tray icon."""
debug_logger.debug("TRAY", "show() called")
if self.tray_icon:
self.tray_icon.show()
def hide(self):
"""Hide the tray icon."""
debug_logger.debug("TRAY", "hide() called")
if self.tray_icon:
self.tray_icon.hide()
@ -88,9 +182,12 @@ class TrayIcon(QWidget):
def _on_activated(self, reason):
"""Handle double-click."""
debug_logger.debug("TRAY", f"Activated with reason: {reason}")
if reason == QSystemTrayIcon.ActivationReason.DoubleClick:
debug_logger.debug("TRAY", "Double-click detected - showing dashboard")
self.show_dashboard.emit()
def set_activity_bar_checked(self, checked: bool):
"""Update checkbox."""
debug_logger.debug("TRAY", f"Setting Activity Bar checked: {checked}")
self.activity_bar_action.setChecked(checked)