From fe265a798162faae5b837ac0d2b37ba6e72428f2 Mon Sep 17 00:00:00 2001 From: Ed_ Date: Sun, 7 Jun 2026 00:34:04 -0400 Subject: [PATCH] feat(app_controller): phase-breakdown expansion of startup_timeline MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Mid-session expansion that was left dirty. Adds 3 main-thread phase markers so the timeline answers 'which phase dominated' instead of just 'how long total': New attrs (all Optional[float], stamped lazily): - _appcontroller_init_done_ts: set by mark_gui_run_started() on its first call (post-init, pre-anything) - _gui_run_started_ts: set by mark_gui_run_started() at the start of App.run() (pre-imgui-bundle C++ init) New property: - cold_start_ts: reads sloppy._SLOPPY_COLD_START_TS so the timeline covers from Python-start to first-frame, not just AppController-init to first-frame (the gap is the main-thread module import chain) New method: - mark_gui_run_started(ts=None): called by App.run() before the imgui bundle setup. Idempotent (safe to call multiple times). Lazily captures _appcontroller_init_done_ts on first call. startup_timeline() now exposes 4 new precomputed deltas: - appcontroller_init_ms: init → AppController done - gui_setup_ms: AppController done → gui_run_started (imgui init) - first_render_ms: gui_run_started → first frame - module_imports_ms: cold_start → init_start - cold_start_to_first_frame_ms: full Python-start → first-frame mark_first_frame_rendered() now also logs the 3-phase breakdown in the stderr line, e.g.: [startup] first frame at 1830.2ms after init [init=33ms, gui_setup=0ms, first_render=1797ms] (rendered 6.5ms AFTER warmup done) --- src/app_controller.py | 65 +++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 63 insertions(+), 2 deletions(-) diff --git a/src/app_controller.py b/src/app_controller.py index 34abff80..a78fe6e4 100644 --- a/src/app_controller.py +++ b/src/app_controller.py @@ -806,9 +806,16 @@ class AppController: [C: src/mcp_client.py:_DDGParser.__init__, src/mcp_client.py:_TextExtractor.__init__] """ # --- Startup timeline (startup_speedup_20260606) --- + # Captured at the very start of __init__ so init_start_ts represents + # the true cold-start entry point. The other timestamps are filled in + # lazily as events occur (warmup_done by on_complete callback, + # first_frame by mark_first_frame_rendered, appcontroller_init_done + # and gui_run_started by mark_gui_run_started). self._init_start_ts: float = time.time() self._warmup_done_ts: Optional[float] = None self._first_frame_ts: Optional[float] = None + self._appcontroller_init_done_ts: Optional[float] = None + self._gui_run_started_ts: Optional[float] = None # --- Locks --- self._send_thread_lock: threading.Lock = threading.Lock() self._disc_entries_lock: threading.Lock = threading.Lock() @@ -1217,6 +1224,15 @@ class AppController: try: warmup_ms = (self._warmup_done_ts - self._init_start_ts) * 1000 if self._warmup_done_ts is not None else 0.0 frame_after_init_ms = (self._first_frame_ts - self._init_start_ts) * 1000 + # Phase breakdown: which main-thread phase dominated? + init_phase_ms = (self._appcontroller_init_done_ts - self._init_start_ts) * 1000 if self._appcontroller_init_done_ts is not None else None + gui_phase_ms = (self._gui_run_started_ts - self._appcontroller_init_done_ts) * 1000 if (self._gui_run_started_ts is not None and self._appcontroller_init_done_ts is not None) else None + render_phase_ms = (self._first_frame_ts - self._gui_run_started_ts) * 1000 if self._gui_run_started_ts is not None else None + phase_parts = [] + if init_phase_ms is not None: phase_parts.append(f"init={init_phase_ms:.0f}ms") + if gui_phase_ms is not None: phase_parts.append(f"gui_setup={gui_phase_ms:.0f}ms") + if render_phase_ms is not None: phase_parts.append(f"first_render={render_phase_ms:.0f}ms") + phase_str = f" [{', '.join(phase_parts)}]" if phase_parts else "" if self._warmup_done_ts is None: gap_str = " (warmup still running at first frame; warmup did NOT block the first frame)" else: @@ -1225,21 +1241,54 @@ class AppController: gap_str = f" (rendered {-delta_ms:.1f}ms BEFORE warmup done \u2014 warmup did NOT block)" else: gap_str = f" (rendered {delta_ms:.1f}ms AFTER warmup done)" - sys.stderr.write(f"[startup] first frame at {frame_after_init_ms:.1f}ms after init (warmup took {warmup_ms:.1f}ms){gap_str}\n") + sys.stderr.write(f"[startup] first frame at {frame_after_init_ms:.1f}ms after init (warmup took {warmup_ms:.1f}ms){phase_str}{gap_str}\n") sys.stderr.flush() except Exception: pass + def mark_gui_run_started(self, ts: "Optional[float]" = None) -> None: + """Called by App.run() before the heavy imgui bundle setup. Captures + _appcontroller_init_done_ts (lazily, since this is the first post-init call) + and _gui_run_started_ts. The 3-phase breakdown in startup_timeline() + then shows: AppController init, GUI bundle setup, first render. + [SDM: src/app_controller.py:mark_gui_run_started] [C: src/gui_2.py:App.run]""" + if self._appcontroller_init_done_ts is None: + self._appcontroller_init_done_ts = ts if ts is not None else time.time() + if self._gui_run_started_ts is None: + self._gui_run_started_ts = ts if ts is not None else time.time() + def startup_timeline(self) -> dict: - """Returns a dict with all startup timestamps and precomputed deltas. Fields: init_start_ts, warmup_done_ts, first_frame_ts, warmup_ms, first_frame_after_init_ms, first_frame_after_warmup_ms. [SDM: src/app_controller.py:startup_timeline] [C: src/api_hooks.py:HookHandler.do_GET /api/startup_timeline]""" + """Returns a dict with all startup timestamps and precomputed deltas. Fields: init_start_ts, appcontroller_init_done_ts, gui_run_started_ts, warmup_done_ts, first_frame_ts, warmup_ms, appcontroller_init_ms, gui_setup_ms, first_render_ms, first_frame_after_init_ms, first_frame_after_warmup_ms. The 3 phase breakdowns answer 'which main-thread phase dominated?': AppController init, GUI bundle setup, first render. [SDM: src/app_controller.py:startup_timeline] [C: src/api_hooks.py:HookHandler.do_GET /api/startup_timeline]""" result: dict = { + "cold_start_ts": self.cold_start_ts, "init_start_ts": self._init_start_ts, + "appcontroller_init_done_ts": self._appcontroller_init_done_ts, + "gui_run_started_ts": self._gui_run_started_ts, "warmup_done_ts": self._warmup_done_ts, "first_frame_ts": self._first_frame_ts, } + if self.cold_start_ts is not None: + result["module_imports_ms"] = (self._init_start_ts - self.cold_start_ts) * 1000 + if self._first_frame_ts is not None: + result["cold_start_to_first_frame_ms"] = (self._first_frame_ts - self.cold_start_ts) * 1000 + else: + result["module_imports_ms"] = None if self._warmup_done_ts is not None: result["warmup_ms"] = (self._warmup_done_ts - self._init_start_ts) * 1000 else: result["warmup_ms"] = None + # 3-phase main-thread breakdown + if self._appcontroller_init_done_ts is not None: + result["appcontroller_init_ms"] = (self._appcontroller_init_done_ts - self._init_start_ts) * 1000 + else: + result["appcontroller_init_ms"] = None + if self._appcontroller_init_done_ts is not None and self._gui_run_started_ts is not None: + result["gui_setup_ms"] = (self._gui_run_started_ts - self._appcontroller_init_done_ts) * 1000 + else: + result["gui_setup_ms"] = None + if self._gui_run_started_ts is not None and self._first_frame_ts is not None: + result["first_render_ms"] = (self._first_frame_ts - self._gui_run_started_ts) * 1000 + else: + result["first_render_ms"] = None if self._first_frame_ts is not None: result["first_frame_after_init_ms"] = (self._first_frame_ts - self._init_start_ts) * 1000 if self._warmup_done_ts is not None: @@ -1251,6 +1300,18 @@ class AppController: result["first_frame_after_warmup_ms"] = None return result + @property + def cold_start_ts(self) -> "Optional[float]": + """Timestamp captured at the very first line of sloppy.py (the entry + point). Used to compute the full 'Python start to first frame' latency, + which is dominated by module imports. None if the entry point didn't + expose _SLOPPY_COLD_START_TS. [SDM: src/app_controller.py:cold_start_ts]""" + try: + import sloppy as _sloppy + return getattr(_sloppy, "_SLOPPY_COLD_START_TS", None) + except (ImportError, AttributeError): + return None + def _on_warmup_complete_for_timeline(self, snap: dict) -> None: """Callback registered with the WarmupManager. Stamps warmup_done_ts and logs the timeline to stderr. [C: src/app_controller.py:startup_timeline]""" self._warmup_done_ts = time.time()