feat(app_controller): phase-breakdown expansion of startup_timeline
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)
This commit is contained in:
+63
-2
@@ -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()
|
||||
|
||||
Reference in New Issue
Block a user