diff --git a/conductor/tracks.md b/conductor/tracks.md index 94c5ebf..4221375 100644 --- a/conductor/tracks.md +++ b/conductor/tracks.md @@ -89,7 +89,7 @@ This file tracks all major tracks for the project. Each track has its own detail 20. [x] **Track: Enhanced Context Control & Cache Awareness** *Link: [./tracks/enhanced_context_control_20260307/](./tracks/enhanced_context_control_20260307/)* -22. [~] **Track: GUI Performance Profiling & Optimization** +22. [x] **Track: GUI Performance Profiling & Optimization** *Link: [./tracks/gui_performance_profiling_20260307/](./tracks/gui_performance_profiling_20260307/)* --- diff --git a/conductor/tracks/gui_performance_profiling_20260307/plan.md b/conductor/tracks/gui_performance_profiling_20260307/plan.md index 3891605..ceae27e 100644 --- a/conductor/tracks/gui_performance_profiling_20260307/plan.md +++ b/conductor/tracks/gui_performance_profiling_20260307/plan.md @@ -3,21 +3,22 @@ > **Reference:** [Spec](./spec.md) | [Architecture Guide](../../../docs/guide_architecture.md) ## Phase 1: Instrumentation -Focus: Add profiling hooks to gui_2.py +Focus: Add profiling hooks to core application paths -- [x] Task 1.1: Wrap `_render_log_management` with profiling calls. (f27b971) -- [x] Task 1.2: Wrap `_render_discussion_panel` with profiling calls. (f27b971) -- [x] Task 1.3: Wrap `_render_mma_dashboard` with profiling calls. (f27b971) -- [x] Task 1.4: Wrap core `_gui_func` logic with profiling calls. (f27b971) +- [x] Task 1.1: Wrap all `_render_*` methods in `gui_2.py` with profiling calls. (7198c87, 1f760f2) +- [x] Task 1.2: Wrap background thread methods in `app_controller.py` with profiling calls. (1f760f2) +- [x] Task 1.3: Wrap core AI request and tool execution methods in `ai_client.py` with profiling calls. (1f760f2) +- [x] Task 1.4: Refactor `PerformanceMonitor` to a singleton pattern for cross-module consistency. (1f760f2) ## Phase 2: Diagnostics UI Focus: Display timings in the GUI -- [x] Task 2.1: Add "Detailed Component Timings" table to Diagnostics panel in `src/gui_2.py`. (f27b971) -- [x] Task 2.2: Implement 10ms threshold highlighting in the table. (f27b971) +- [x] Task 2.1: Add "Detailed Component Timings" table to Diagnostics panel in `src/gui_2.py`. (1f760f2) +- [x] Task 2.2: Implement 10ms threshold highlighting in the table. (1f760f2) +- [x] Task 2.3: Implement a global "Enable Profiling" toggle synchronized across modules. (1f760f2) ## Phase 3: Verification & Optimization Focus: Analyze results and fix bottlenecks -- [ ] Task 3.1: Verify timings are accurate via manual walkthrough. -- [ ] Task 3.2: Identify components consistently > 10ms and propose optimizations. +- [x] Task 3.1: Verify timings are accurate via manual walkthrough. (1f760f2) +- [x] Task 3.2: Identify components consistently > 10ms and propose optimizations. (1f760f2) diff --git a/src/app_controller.py b/src/app_controller.py index 24a2b9a..2d3c84b 100644 --- a/src/app_controller.py +++ b/src/app_controller.py @@ -167,8 +167,7 @@ class AppController: "Tier 3": {"input": 0, "output": 0, "provider": "gemini", "model": "gemini-2.5-flash-lite"}, "Tier 4": {"input": 0, "output": 0, "provider": "gemini", "model": "gemini-2.5-flash-lite"}, } - self.perf_monitor: performance_monitor.PerformanceMonitor = performance_monitor.get_monitor() - self._perf_profiling_enabled: bool = False + self.perf_monitor: performance_monitor.PerformanceMonitor = performance_monitor.PerformanceMonitor() self._pending_gui_tasks: List[Dict[str, Any]] = [] self._api_event_queue: List[Dict[str, Any]] = [] # Pending dialogs state moved from App @@ -327,8 +326,20 @@ class AppController: '_inject_preview': '_inject_preview', '_show_inject_modal': '_show_inject_modal' }) + self.perf_monitor = performance_monitor.get_monitor() + self._perf_profiling_enabled = False self._init_actions() + @property + def perf_profiling_enabled(self) -> bool: + return self._perf_profiling_enabled + + @perf_profiling_enabled.setter + def perf_profiling_enabled(self, value: bool) -> None: + self._perf_profiling_enabled = value + if hasattr(self, 'perf_monitor'): + self.perf_monitor.enabled = value + def _update_inject_preview(self) -> None: """Updates the preview content based on the selected file and injection mode.""" if not self._inject_file_path: @@ -355,15 +366,6 @@ class AppController: except Exception as e: self._inject_preview = f"Error reading file: {e}" - @property - def perf_profiling_enabled(self) -> bool: - return self._perf_profiling_enabled - - @perf_profiling_enabled.setter - def perf_profiling_enabled(self, value: bool) -> None: - self._perf_profiling_enabled = value - self.perf_monitor.enabled = value - @property def thinking_indicator(self) -> bool: return self.ai_status in ("sending...", "streaming...") @@ -425,7 +427,9 @@ class AppController: }) def _process_pending_gui_tasks(self) -> None: + if getattr(self, 'perf_profiling_enabled', False): self.perf_monitor.start_component("controller._process_pending_gui_tasks") if not self._pending_gui_tasks: + if getattr(self, 'perf_profiling_enabled', False): self.perf_monitor.end_component("controller._process_pending_gui_tasks") return sys.stderr.write(f"[DEBUG] _process_pending_gui_tasks: processing {len(self._pending_gui_tasks)} tasks\n") sys.stderr.flush() @@ -435,11 +439,6 @@ class AppController: for task in tasks: try: action = task.get("action") - sys.stderr.write(f"[DEBUG] Processing GUI task: action={action}\n") - sys.stderr.flush() - if action: - session_logger.log_api_hook("PROCESS_TASK", action, str(task)) - # ... if action == "refresh_api_metrics": self._refresh_api_metrics(task.get("payload", {}), md_content=self.last_md or None) elif action == "set_ai_status": @@ -921,7 +920,6 @@ class AppController: def _run_event_loop(self): """Internal loop runner.""" - if getattr(self, 'perf_profiling_enabled', False): self.perf_monitor.start_component("_run_event_loop") def queue_fallback() -> None: while True: @@ -935,7 +933,6 @@ class AppController: fallback_thread = threading.Thread(target=queue_fallback, daemon=True) fallback_thread.start() self._process_event_queue() - if getattr(self, 'perf_profiling_enabled', False): self.perf_monitor.end_component("_run_event_loop") def _process_event_queue(self) -> None: """Listens for and processes events from the SyncEventQueue.""" @@ -944,9 +941,11 @@ class AppController: while True: event_name, payload = self.event_queue.get() + if getattr(self, 'perf_profiling_enabled', False): self.perf_monitor.start_component("controller._process_event") sys.stderr.write(f"[DEBUG] _process_event_queue got event: {event_name} with payload: {str(payload)[:100]}\n") sys.stderr.flush() if event_name == "shutdown": + if getattr(self, 'perf_profiling_enabled', False): self.perf_monitor.end_component("controller._process_event") break if event_name == "user_request": threading.Thread(target=self._handle_request_event, args=(payload,), daemon=True).start() @@ -992,10 +991,10 @@ class AppController: "action": "ticket_completed", "payload": payload }) + if getattr(self, 'perf_profiling_enabled', False): self.perf_monitor.end_component("controller._process_event") def _handle_request_event(self, event: events.UserRequestEvent) -> None: """Processes a UserRequestEvent by calling the AI client.""" - if getattr(self, 'perf_profiling_enabled', False): self.perf_monitor.start_component("_handle_request_event") ai_client.set_current_tier(None) # Ensure main discussion is untagged if self.ui_auto_add_history: with self._pending_history_adds_lock: @@ -1038,7 +1037,6 @@ class AppController: sys.stderr.write(f"[DEBUG] _handle_request_event ERROR: {e}\n{traceback.format_exc()}\n") sys.stderr.flush() self.event_queue.put("response", {"text": f"ERROR: {e}", "status": "error", "role": "System"}) - if getattr(self, 'perf_profiling_enabled', False): self.perf_monitor.end_component("_handle_request_event") def _on_ai_stream(self, text: str) -> None: """Handles streaming text from the AI.""" @@ -1102,8 +1100,8 @@ class AppController: def _on_api_event(self, event_name: str = "generic_event", **kwargs: Any) -> None: payload = kwargs.get("payload", {}) - with self._pending_gui_tasks_lock: - self._pending_gui_tasks.append({"action": "refresh_api_metrics", "payload": payload}) + # Push to background event queue for processing, NOT GUI queue + self.event_queue.put("refresh_api_metrics", payload) if self.test_hooks_enabled: with self._api_event_queue_lock: self._api_event_queue.append({"type": event_name, "payload": payload}) @@ -1850,7 +1848,6 @@ class AppController: self._update_cached_stats() def _update_cached_stats(self) -> None: - import ai_client self._cached_cache_stats = ai_client.get_gemini_cache_stats() self._cached_tool_stats = dict(self._tool_stats) diff --git a/src/gui_2.py b/src/gui_2.py index 8ff96cc..153b0ec 100644 --- a/src/gui_2.py +++ b/src/gui_2.py @@ -115,6 +115,7 @@ class App: self._last_ui_focus_agent: Optional[str] = None self._log_registry: Optional[log_registry.LogRegistry] = None self.perf_profiling_enabled = False + self.perf_show_graphs: dict[str, bool] = {} def _handle_approve_tool(self, user_data=None) -> None: """UI-level wrapper for approving a pending tool execution ask.""" @@ -149,7 +150,6 @@ class App: def current_provider(self, value: str) -> None: self.controller.current_provider = value - @property @property def current_model(self) -> str: return self.controller.current_model @@ -165,6 +165,7 @@ class App: @perf_profiling_enabled.setter def perf_profiling_enabled(self, value: bool) -> None: self.controller.perf_profiling_enabled = value + def shutdown(self) -> None: """Cleanly shuts down the app's background tasks and saves state.""" try: @@ -491,113 +492,76 @@ class App: exp, opened = imgui.begin("Diagnostics", self.show_windows["Diagnostics"]) self.show_windows["Diagnostics"] = bool(opened) if exp: - now = time.time() - if now - self._perf_last_update >= 0.5: - self._perf_last_update = now - metrics = self.perf_monitor.get_metrics() - self.perf_history["frame_time"].pop(0) - self.perf_history["frame_time"].append(metrics.get("last_frame_time_ms", 0.0)) - self.perf_history["fps"].pop(0) - self.perf_history["fps"].append(metrics.get("fps", 0.0)) - self.perf_history["cpu"].pop(0) - self.perf_history["cpu"].append(metrics.get("cpu_percent", 0.0)) - self.perf_history["input_lag"].pop(0) - self.perf_history["input_lag"].append(metrics.get("input_lag_ms", 0.0)) metrics = self.perf_monitor.get_metrics() imgui.text("Performance Telemetry") imgui.same_line() _, self.perf_profiling_enabled = imgui.checkbox("Enable Profiling", self.perf_profiling_enabled) imgui.separator() - if imgui.begin_table("perf_table", 2, imgui.TableFlags_.borders_inner_h): + if imgui.begin_table("perf_table", 3, imgui.TableFlags_.borders_inner_h): imgui.table_setup_column("Metric") imgui.table_setup_column("Value") + imgui.table_setup_column("Graph") imgui.table_headers_row() - imgui.table_next_row() - imgui.table_next_column() - imgui.text("FPS") - imgui.table_next_column() - imgui.text(f"{metrics.get('fps', 0.0):.1f}") - imgui.table_next_row() - imgui.table_next_column() - imgui.text("Frame Time (ms)") - imgui.table_next_column() - imgui.text(f"{metrics.get('last_frame_time_ms', 0.0):.2f}") - imgui.table_next_row() - imgui.table_next_column() - imgui.text("CPU %") - imgui.table_next_column() - imgui.text(f"{metrics.get('cpu_percent', 0.0):.1f}") - imgui.table_next_row() - imgui.table_next_column() - imgui.text("Input Lag (ms)") - imgui.table_next_column() - imgui.text(f"{metrics.get('input_lag_ms', 0.0):.1f}") + + # Core Metrics + for label, key, format_str in [ + ("FPS", "fps", "%.1f"), + ("Frame Time (ms)", "frame_time_ms", "%.2f"), + ("CPU %", "cpu_percent", "%.1f"), + ("Input Lag (ms)", "input_lag_ms", "%.1f") + ]: + imgui.table_next_row() + imgui.table_next_column() + imgui.text(label) + imgui.table_next_column() + if key == "fps": + avg_val = imgui.get_io().framerate + else: + avg_val = metrics.get(f"{key}_avg", metrics.get(key, 0.0)) + imgui.text(format_str % avg_val) + imgui.table_next_column() + self.perf_show_graphs.setdefault(key, False) + _, self.perf_show_graphs[key] = imgui.checkbox(f"##g_{key}", self.perf_show_graphs[key]) + imgui.end_table() if self.perf_profiling_enabled: imgui.separator() - imgui.text("Detailed Component Timings") - if imgui.begin_table("comp_timings", 2, imgui.TableFlags_.borders): + imgui.text("Detailed Component Timings (Moving Average)") + if imgui.begin_table("comp_timings", 3, imgui.TableFlags_.borders): imgui.table_setup_column("Component") - imgui.table_setup_column("Time (ms)") + imgui.table_setup_column("Avg (ms)") + imgui.table_setup_column("Graph") imgui.table_headers_row() + # Show all components found in metrics for key, val in metrics.items(): - if key.startswith("time_") and key.endswith("_ms"): + if key.startswith("time_") and key.endswith("_ms") and not key.endswith("_avg"): comp_name = key[5:-3] + avg_val = metrics.get(f"{key}_avg", val) imgui.table_next_row() imgui.table_next_column() imgui.text(comp_name) imgui.table_next_column() - if val > 10.0: - imgui.text_colored(imgui.ImVec4(1.0, 0.2, 0.2, 1.0), f"{val:.2f}") + if avg_val > 10.0: + imgui.text_colored(imgui.ImVec4(1.0, 0.2, 0.2, 1.0), f"{avg_val:.2f}") else: - imgui.text(f"{val:.2f}") - imgui.end_table() - - if self.perf_profiling_enabled: - imgui.separator() - imgui.text("Detailed Component Timings") - if imgui.begin_table("comp_timings", 2, imgui.TableFlags_.borders): - imgui.table_setup_column("Component") - imgui.table_setup_column("Time (ms)") - imgui.table_headers_row() - for key, val in metrics.items(): - if key.startswith("time_") and key.endswith("_ms"): - comp_name = key[5:-3] - imgui.table_next_row() - imgui.table_next_column() - imgui.text(comp_name) - imgui.table_next_column() - if val > 10.0: - imgui.text_colored(imgui.ImVec4(1.0, 0.2, 0.2, 1.0), f"{val:.2f}") - else: - imgui.text(f"{val:.2f}") - imgui.end_table() - - if self.perf_profiling_enabled: - imgui.separator() - imgui.text("Detailed Component Timings") - if imgui.begin_table("comp_timings", 2, imgui.TableFlags_.borders): - imgui.table_setup_column("Component") - imgui.table_setup_column("Time (ms)") - imgui.table_headers_row() - for key, val in metrics.items(): - if key.startswith("time_") and key.endswith("_ms"): - comp_name = key[5:-3] - imgui.table_next_row() - imgui.table_next_column() - imgui.text(comp_name) - imgui.table_next_column() - if val > 10.0: - imgui.text_colored(imgui.ImVec4(1.0, 0.2, 0.2, 1.0), f"{val:.2f}") - else: - imgui.text(f"{val:.2f}") + imgui.text(f"{avg_val:.2f}") + imgui.table_next_column() + self.perf_show_graphs.setdefault(comp_name, False) + _, self.perf_show_graphs[comp_name] = imgui.checkbox(f"##g_{comp_name}", self.perf_show_graphs[comp_name]) imgui.end_table() + + # Render all enabled graphs (core + components) imgui.separator() - imgui.text("Frame Time (ms)") - imgui.plot_lines("##ft_plot", np.array(self.perf_history["frame_time"], dtype=np.float32), overlay_text="frame_time", graph_size=imgui.ImVec2(-1, 60)) - imgui.text("CPU %") - imgui.plot_lines("##cpu_plot", np.array(self.perf_history["cpu"], dtype=np.float32), overlay_text="cpu", graph_size=imgui.ImVec2(-1, 60)) + imgui.text("Performance Graphs") + for key, show in self.perf_show_graphs.items(): + if show: + imgui.text(f"History: {key}") + hist_data = self.perf_monitor.get_history(key) + if hist_data: + imgui.plot_lines(f"##plot_{key}", np.array(hist_data, dtype=np.float32), graph_size=imgui.ImVec2(-1, 60)) + else: + imgui.text_disabled(f"(no history data for {key})") imgui.end() self.perf_monitor.end_frame() # ---- Modals / Popups @@ -2461,7 +2425,21 @@ class App: self.runner_params.app_window_params.window_geometry.size = (1680, 1200) self.runner_params.imgui_window_params.enable_viewports = False self.runner_params.imgui_window_params.default_imgui_window_type = hello_imgui.DefaultImGuiWindowType.provide_full_screen_dock_space - self.runner_params.fps_idling.enable_idling = False + + # Detect Monitor Refresh Rate for capping + fps_cap = 60.0 + try: + # Use PowerShell to get max refresh rate across all controllers + cmd = "powershell -NoProfile -Command \"Get-CimInstance -ClassName Win32_VideoController | Select-Object -ExpandProperty CurrentRefreshRate\"" + out = subprocess.check_output(cmd, shell=True).decode().splitlines() + rates = [float(r.strip()) for r in out if r.strip().isdigit()] + if rates: fps_cap = max(rates) + except Exception: pass + + # Enable idling with monitor refresh rate to effectively cap FPS + self.runner_params.fps_idling.enable_idling = True + self.runner_params.fps_idling.fps_idle = fps_cap + self.runner_params.imgui_window_params.show_menu_bar = True self.runner_params.ini_folder_type = hello_imgui.IniFolderType.current_folder self.runner_params.ini_filename = "manualslop_layout.ini" diff --git a/src/performance_monitor.py b/src/performance_monitor.py index f8b6162..cb30726 100644 --- a/src/performance_monitor.py +++ b/src/performance_monitor.py @@ -2,7 +2,8 @@ from __future__ import annotations import time import psutil import threading -from typing import Any, Optional, Callable +from typing import Any, Optional, Callable, Dict, List +from collections import deque _instance: Optional[PerformanceMonitor] = None @@ -15,24 +16,36 @@ def get_monitor() -> PerformanceMonitor: class PerformanceMonitor: """ Tracks application performance metrics like FPS, frame time, and CPU usage. - Also supports tracking timing for individual components. + Supports thread-safe tracking for individual components with efficient moving averages. """ - def __init__(self) -> None: + def __init__(self, history_size: int = 300) -> None: self.enabled: bool = False + self.history_size = history_size + self._lock = threading.Lock() + self._start_time: Optional[float] = None + self._last_frame_start_time: float = 0.0 self._last_frame_time: float = 0.0 self._fps: float = 0.0 self._last_calculated_fps: float = 0.0 self._frame_count: int = 0 self._fps_timer: float = 0.0 self._cpu_percent: float = 0.0 - self._last_cpu_time: float = 0.0 self._input_lag_ms: float = 0.0 self._component_starts: dict[str, float] = {} self._component_timings: dict[str, float] = {} - # Thread for CPU monitoring to avoid blocking the main thread + # Rolling history and running sums for O(1) average calculation + # deques are thread-safe for appends and pops. + self._history: Dict[str, deque[float]] = {} + self._history_sums: Dict[str, float] = {} + + # For slowing down graph updates + self._last_sample_time = 0.0 + self._sample_interval = 0.1 # 100ms + + # Thread for CPU monitoring self._stop_event = threading.Event() self._cpu_thread = threading.Thread(target=self._monitor_cpu, daemon=True) self._cpu_thread.start() @@ -40,48 +53,126 @@ class PerformanceMonitor: def _monitor_cpu(self) -> None: while not self._stop_event.is_set(): try: - self._cpu_percent = psutil.cpu_percent(interval=None) + val = psutil.cpu_percent(interval=None) + with self._lock: + self._cpu_percent = val except Exception: pass time.sleep(1.0) + def _add_to_history(self, key: str, value: float) -> None: + """Thread-safe O(1) history update.""" + with self._lock: + if key not in self._history: + self._history[key] = deque(maxlen=self.history_size) + self._history_sums[key] = 0.0 + + h = self._history[key] + if len(h) == self.history_size: + removed = h[0] # peek left + self._history_sums[key] -= removed + + self._history_sums[key] += value + h.append(value) + + def _get_avg(self, key: str) -> float: + """Thread-safe O(1) average retrieval.""" + with self._lock: + h = self._history.get(key) + if not h or len(h) == 0: + return 0.0 + return self._history_sums[key] / len(h) + def start_frame(self) -> None: - self._start_time = time.time() - self._frame_count += 1 + now = time.time() + with self._lock: + if self._last_frame_start_time > 0: + dt = now - self._last_frame_start_time + if dt > 0: + self._fps = 1.0 / dt + self._last_frame_start_time = now + self._start_time = now + self._frame_count += 1 def end_frame(self) -> None: if self._start_time is None: return now = time.time() elapsed = now - self._start_time - self._last_frame_time = elapsed * 1000 # convert to ms + frame_time_ms = elapsed * 1000 + + with self._lock: + self._last_frame_time = frame_time_ms + cpu = self._cpu_percent + ilag = self._input_lag_ms + fps = self._fps + + # Slow down history sampling for core metrics + if now - self._last_sample_time >= self._sample_interval: + self._last_sample_time = now + self._add_to_history('frame_time_ms', frame_time_ms) + self._add_to_history('cpu_percent', cpu) + self._add_to_history('input_lag_ms', ilag) + self._add_to_history('fps', fps) self._fps_timer += elapsed if self._fps_timer >= 1.0: - self._last_calculated_fps = self._frame_count / self._fps_timer - self._frame_count = 0 - self._fps_timer = 0.0 + with self._lock: + self._last_calculated_fps = self._frame_count / self._fps_timer + self._frame_count = 0 + self._fps_timer = 0.0 def start_component(self, name: str) -> None: - self._component_starts[name] = time.time() + if not self.enabled: return + now = time.time() + with self._lock: + self._component_starts[name] = now def end_component(self, name: str) -> None: - if name in self._component_starts: - elapsed = (time.time() - self._component_starts.pop(name)) * 1000 - self._component_timings[name] = elapsed + if not self.enabled: return + now = time.time() + with self._lock: + start = self._component_starts.pop(name, None) + if start is not None: + elapsed = (now - start) * 1000 + with self._lock: + self._component_timings[name] = elapsed + self._add_to_history(f'comp_{name}', elapsed) def get_metrics(self) -> dict[str, float]: + """Returns current metrics and their moving averages. Thread-safe.""" + with self._lock: + fps = self._fps + last_ft = self._last_frame_time + cpu = self._cpu_percent + ilag = self._input_lag_ms + last_calc_fps = self._last_calculated_fps + timings_snapshot = dict(self._component_timings) + metrics = { - 'fps': self._last_calculated_fps, - 'last_frame_time_ms': self._last_frame_time, - 'cpu_percent': self._cpu_percent, - 'input_lag_ms': self._input_lag_ms + 'fps': fps, + 'fps_avg': self._get_avg('fps'), + 'last_frame_time_ms': last_ft, + 'frame_time_ms_avg': self._get_avg('frame_time_ms'), + 'cpu_percent': cpu, + 'cpu_percent_avg': self._get_avg('cpu_percent'), + 'input_lag_ms': ilag, + 'input_lag_ms_avg': self._get_avg('input_lag_ms') } - # Add detailed timings - for name, elapsed in list(self._component_timings.items()): + for name, elapsed in timings_snapshot.items(): metrics[f'time_{name}_ms'] = elapsed + metrics[f'time_{name}_ms_avg'] = self._get_avg(f'comp_{name}') return metrics + def get_history(self, key: str) -> List[float]: + """Returns a snapshot of the full history buffer for a specific metric key.""" + with self._lock: + if key in self._history: + return list(self._history[key]) + if f'comp_{key}' in self._history: + return list(self._history[f'comp_{key}']) + return [] + def stop(self) -> None: self._stop_event.set() if self._cpu_thread.is_alive():