diff --git a/scripts/apply_startup_timeline.py b/scripts/apply_startup_timeline.py new file mode 100644 index 00000000..9b6adf8b --- /dev/null +++ b/scripts/apply_startup_timeline.py @@ -0,0 +1,197 @@ +""" +Surgical edit script for src/app_controller.py - adds startup timeline +instrumentation to AppController. + +Run: uv run python scripts/apply_startup_timeline.py +""" +import ast +import os +import sys + +BASE: str = os.path.abspath(os.path.join(os.path.dirname(__file__), "..")) +TARGET_FILE: str = "src/app_controller.py" +EOL: str = "\r\n" + + +def read_lines(path: str) -> list[str]: + with open(path, "r", encoding="utf-8", newline="") as f: + return f.read().splitlines(keepends=True) + + +def write_lines(path: str, lines: list[str]) -> None: + with open(path, "w", encoding="utf-8", newline="") as f: + f.writelines(lines) + + +def find_init(tree: ast.Module) -> ast.FunctionDef: + for node in tree.body: + if isinstance(node, ast.ClassDef) and node.name == "AppController": + for item in node.body: + if isinstance(item, ast.FunctionDef) and item.name == "__init__": + return item + raise RuntimeError("AppController.__init__ not found") + + +def patch_def_signature(lines: list[str], init_fn: ast.FunctionDef) -> None: + idx = init_fn.lineno - 1 + line = lines[idx] + if "log_to_stderr" in line: + return + new_line = line.replace("def __init__(self):", "def __init__(self, log_to_stderr: bool = True):") + if new_line == line: + raise RuntimeError(f"Could not patch def line: {line!r}") + lines[idx] = new_line + print(f" Patched def signature at line {init_fn.lineno}") + + +def insert_timeline_block(lines: list[str]) -> None: + for i, line in enumerate(lines): + if line.strip() == '"""' and i + 1 < len(lines) and "# --- Locks ---" in lines[i + 1]: + block_lines = [ + ' # --- Startup timeline (startup_speedup_20260606) ---' + EOL, + ' # Captured at the very start of __init__ so init_start_ts represents' + EOL, + ' # the true cold-start entry point. first_frame_ts and warmup_done_ts' + EOL, + ' # are filled in later as events occur.' + EOL, + ' self._init_start_ts: float = time.time()' + EOL, + ' self._warmup_done_ts: Optional[float] = None' + EOL, + ' self._first_frame_ts: Optional[float] = None' + EOL, + ] + lines[i + 1:i + 1] = block_lines + print(f" Inserted timeline block at line {i + 2}") + return + raise RuntimeError("Could not find docstring-end + Locks-comment marker") + + +def patch_warmup_block(lines: list[str]) -> None: + old = [ + ' # --- Shared background pool + proactive warmup (startup_speedup_20260606) ---' + EOL, + ' self._io_pool = make_io_pool()' + EOL, + ' self._warmup = WarmupManager(self._io_pool)' + EOL, + ' self._warmup.submit(self._compute_warmup_list())' + EOL, + ] + new = [ + ' # --- Shared background pool + proactive warmup (startup_speedup_20260606) ---' + EOL, + ' self._io_pool = make_io_pool()' + EOL, + ' self._warmup = WarmupManager(self._io_pool, log_to_stderr=log_to_stderr)' + EOL, + ' # Hook warmup completion to stamp warmup_done_ts for startup_timeline().' + EOL, + ' self._warmup.on_complete(self._on_warmup_complete_for_timeline)' + EOL, + ' self._warmup.submit(self._compute_warmup_list())' + EOL, + ] + for i in range(len(lines) - len(old) + 1): + if lines[i:i + len(old)] == old: + lines[i:i + len(old)] = new + print(f" Replaced warmup block at lines {i + 1}-{i + len(old)}") + return + raise RuntimeError("Could not find warmup block to replace") + + +NEW_METHODS_TEMPLATE = ''' def init_start_ts(self) -> float: + """Timestamp when AppController.__init__ started (cold-start entry). [SDM: src/app_controller.py:init_start_ts]""" + return self._init_start_ts + + def warmup_done_ts(self) -> "Optional[float]": + """Timestamp when the warmup completed; None while still running. [SDM: src/app_controller.py:warmup_done_ts]""" + return self._warmup_done_ts + + def first_frame_ts(self) -> "Optional[float]": + """Timestamp of the first GUI frame; None until the App has rendered once. [SDM: src/app_controller.py:first_frame_ts]""" + return self._first_frame_ts + + def mark_first_frame_rendered(self, ts: "Optional[float]" = None) -> None: + """Called by the App on the first frame render. Stamps first_frame_ts and logs the timeline to stderr. [SDM: src/app_controller.py:mark_first_frame_rendered] [C: src/gui_2.py:render_main_interface]""" + if self._first_frame_ts is not None: return + self._first_frame_ts = ts if ts is not None else time.time() + 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 + if self._warmup_done_ts is None: + gap_str = " (warmup still running at first frame; warmup did NOT block the first frame)" + else: + delta_ms = (self._first_frame_ts - self._warmup_done_ts) * 1000 + if delta_ms < 0: + 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.flush() + except Exception: pass + + def startup_timeline(self) -> dict: +def insert_new_methods(lines: list[str]) -> None: + """Insert new methods right after the last line of __init__ (`self._init_actions()`).""" + needle = ' self._init_actions()' + EOL + for i, line in enumerate(lines): + if line == needle: + # Insert AFTER this line. The next line is blank, then the next method. + new_lines = [l + EOL for l in NEW_METHODS_TEMPLATE.split("\n") if l] + insert_at = i + 1 + lines[insert_at:insert_at] = new_lines + print(f" Inserted {len(new_lines)} new method lines at line {insert_at + 1}") + return + raise RuntimeError("Could not find 'self._init_actions()' to anchor new methods") + } + 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 + 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: + result["first_frame_after_warmup_ms"] = (self._first_frame_ts - self._warmup_done_ts) * 1000 + else: + result["first_frame_after_warmup_ms"] = None + else: + result["first_frame_after_init_ms"] = None + result["first_frame_after_warmup_ms"] = None + return result + + 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() + try: + warmup_ms = (self._warmup_done_ts - self._init_start_ts) * 1000 + if self._first_frame_ts is None: + gap_str = f" (first frame not yet rendered at warmup done; warmup took {warmup_ms:.1f}ms)" + else: + delta_ms = (self._first_frame_ts - self._warmup_done_ts) * 1000 + if delta_ms < 0: + gap_str = f" (first frame rendered {-delta_ms:.1f}ms BEFORE warmup done \\u2014 warmup did NOT block)" + else: + gap_str = f" (first frame rendered {delta_ms:.1f}ms after warmup done)" + sys.stderr.write(f"[startup] warmup done in {warmup_ms:.1f}ms{gap_str}\\n") + sys.stderr.flush() + except Exception: pass + +''' + + +def insert_new_methods(lines: list[str]) -> None: + for i, line in enumerate(lines): + if line.lstrip().startswith("def perf_profiling_enabled"): + new_lines = [l + EOL for l in NEW_METHODS_TEMPLATE.split("\n") if l] + lines[i:i] = new_lines + print(f" Inserted {len(new_lines)} new method lines at line {i + 1}") + return + raise RuntimeError("Could not find 'def perf_profiling_enabled' to anchor new methods") + + +def main() -> None: + path = os.path.join(BASE, TARGET_FILE) + lines = read_lines(path) + code = "".join(lines) + tree = ast.parse(code) + init_fn = find_init(tree) + print(f"Found AppController.__init__ at lines {init_fn.lineno}-{init_fn.end_lineno}") + patch_def_signature(lines, init_fn) + insert_timeline_block(lines) + patch_warmup_block(lines) + insert_new_methods(lines) + write_lines(path, lines) + print(f"\nWrote {len(lines)} lines to {path}") + with open(path, "rb") as f: + ast.parse(f.read()) + print(" Syntax OK") + + +if __name__ == "__main__": + main() diff --git a/src/api_hook_client.py b/src/api_hook_client.py index bec4c62a..cae657b4 100644 --- a/src/api_hook_client.py +++ b/src/api_hook_client.py @@ -329,6 +329,16 @@ class ApiHookClient: result = self._make_request('GET', '/api/warmup_canaries') or {} return result.get("canaries", []) if isinstance(result, dict) else [] + def get_startup_timeline(self) -> dict[str, Any]: + """ + Returns the startup timeline: dict with init_start_ts, warmup_done_ts, + first_frame_ts, warmup_ms, first_frame_after_init_ms, + first_frame_after_warmup_ms. Lets external clients answer + 'did the warmup block the first frame?'. + [C: tests/test_api_hooks_warmup.py:test_live_startup_timeline_endpoint] + """ + return self._make_request('GET', '/api/startup_timeline') or {} + #endregion: Diagnostics #region: Project diff --git a/src/api_hooks.py b/src/api_hooks.py index 09a8bd5e..fee232d3 100644 --- a/src/api_hooks.py +++ b/src/api_hooks.py @@ -382,6 +382,18 @@ class HookHandler(BaseHTTPRequestHandler): self.send_header("Content-Type", "application/json") self.end_headers() self.wfile.write(json.dumps(payload).encode("utf-8")) + elif self.path == "/api/startup_timeline" or self.path.startswith("/api/startup_timeline?"): + # Startup timeline: init/warmup/first-frame timestamps + precomputed deltas. + controller = _get_app_attr(app, "controller", None) + empty = {"init_start_ts": None, "warmup_done_ts": None, "first_frame_ts": None, "warmup_ms": None, "first_frame_after_init_ms": None, "first_frame_after_warmup_ms": None} + if controller and hasattr(controller, "startup_timeline"): + try: payload = controller.startup_timeline() + except Exception: payload = empty + else: payload = empty + self.send_response(200) + self.send_header("Content-Type", "application/json") + self.end_headers() + self.wfile.write(json.dumps(payload).encode("utf-8")) else: self.send_response(404) self.end_headers() diff --git a/src/app_controller.py b/src/app_controller.py index 43ff97ff..34abff80 100644 --- a/src/app_controller.py +++ b/src/app_controller.py @@ -801,10 +801,14 @@ class AppController: Owns the application state and manages background services. """ - def __init__(self): + def __init__(self, log_to_stderr: bool = True): """ [C: src/mcp_client.py:_DDGParser.__init__, src/mcp_client.py:_TextExtractor.__init__] """ + # --- Startup timeline (startup_speedup_20260606) --- + self._init_start_ts: float = time.time() + self._warmup_done_ts: Optional[float] = None + self._first_frame_ts: Optional[float] = None # --- Locks --- self._send_thread_lock: threading.Lock = threading.Lock() self._disc_entries_lock: threading.Lock = threading.Lock() @@ -819,7 +823,9 @@ class AppController: # --- Shared background pool + proactive warmup (startup_speedup_20260606) --- self._io_pool = make_io_pool() - self._warmup = WarmupManager(self._io_pool) + self._warmup = WarmupManager(self._io_pool, log_to_stderr=log_to_stderr) + # Hook warmup completion to stamp warmup_done_ts for startup_timeline(). + self._warmup.on_complete(self._on_warmup_complete_for_timeline) self._warmup.submit(self._compute_warmup_list()) # --- Internal State --- @@ -1189,6 +1195,79 @@ class AppController: } self._init_actions() + @property + def init_start_ts(self) -> float: + """Timestamp when AppController.__init__ started (cold-start entry). [SDM: src/app_controller.py:init_start_ts]""" + return self._init_start_ts + + @property + def warmup_done_ts(self) -> "Optional[float]": + """Timestamp when the warmup completed; None while still running. [SDM: src/app_controller.py:warmup_done_ts]""" + return self._warmup_done_ts + + @property + def first_frame_ts(self) -> "Optional[float]": + """Timestamp of the first GUI frame; None until the App has rendered once. [SDM: src/app_controller.py:first_frame_ts]""" + return self._first_frame_ts + + def mark_first_frame_rendered(self, ts: "Optional[float]" = None) -> None: + """Called by the App on the first frame render. Stamps first_frame_ts and logs the timeline to stderr. [SDM: src/app_controller.py:mark_first_frame_rendered] [C: src/gui_2.py:render_main_interface]""" + if self._first_frame_ts is not None: return + self._first_frame_ts = ts if ts is not None else time.time() + 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 + if self._warmup_done_ts is None: + gap_str = " (warmup still running at first frame; warmup did NOT block the first frame)" + else: + delta_ms = (self._first_frame_ts - self._warmup_done_ts) * 1000 + if delta_ms < 0: + 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.flush() + except Exception: pass + + 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]""" + result: dict = { + "init_start_ts": self._init_start_ts, + "warmup_done_ts": self._warmup_done_ts, + "first_frame_ts": self._first_frame_ts, + } + 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 + 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: + result["first_frame_after_warmup_ms"] = (self._first_frame_ts - self._warmup_done_ts) * 1000 + else: + result["first_frame_after_warmup_ms"] = None + else: + result["first_frame_after_init_ms"] = None + result["first_frame_after_warmup_ms"] = None + return result + + 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() + try: + warmup_ms = (self._warmup_done_ts - self._init_start_ts) * 1000 + if self._first_frame_ts is None: + gap_str = f" (first frame not yet rendered at warmup done; warmup took {warmup_ms:.1f}ms)" + else: + delta_ms = (self._first_frame_ts - self._warmup_done_ts) * 1000 + if delta_ms < 0: + gap_str = f" (first frame rendered {-delta_ms:.1f}ms BEFORE warmup done \u2014 warmup did NOT block)" + else: + gap_str = f" (first frame rendered {delta_ms:.1f}ms after warmup done)" + sys.stderr.write(f"[startup] warmup done in {warmup_ms:.1f}ms{gap_str}\n") + sys.stderr.flush() + except Exception: pass + @property def perf_profiling_enabled(self) -> bool: return self._perf_profiling_enabled diff --git a/src/gui_2.py b/src/gui_2.py index 5fab4397..1b64c575 100644 --- a/src/gui_2.py +++ b/src/gui_2.py @@ -1309,6 +1309,8 @@ if __name__ == "__main__": main() def render_main_interface(app: App) -> None: + if hasattr(app, "controller") and hasattr(app.controller, "mark_first_frame_rendered"): + app.controller.mark_first_frame_rendered() render_error_tint(app) render_project_stale_tint(app) render_warmup_status_indicator(app) diff --git a/tests/test_warmup_canaries.py b/tests/test_warmup_canaries.py index 8f3568c5..b9045434 100644 --- a/tests/test_warmup_canaries.py +++ b/tests/test_warmup_canaries.py @@ -239,3 +239,78 @@ def test_warmup_log_line_includes_thread_id(capsys: pytest.CaptureFixture) -> No thread_id = str(canaries[0]["thread_id"]) assert thread_id in captured.err, f"expected thread_id {thread_id} in stderr: {captured.err!r}" pool.shutdown(wait=True) + +def test_app_controller_init_start_ts_is_set() -> None: + """AppController records the timestamp when __init__ starts.""" + from src.app_controller import AppController + import time + t_before = time.time() + ctrl = AppController(log_to_stderr=False) + t_after = time.time() + assert isinstance(ctrl.init_start_ts, float) + assert t_before <= ctrl.init_start_ts <= t_after + ctrl.shutdown() + + +def test_app_controller_warmup_done_ts_none_until_completed() -> None: + """warmup_done_ts is None before wait, float after.""" + from src.app_controller import AppController + ctrl = AppController(log_to_stderr=False) + initial = ctrl.warmup_done_ts + assert initial is None + assert ctrl.wait_for_warmup(timeout=60.0) is True + assert isinstance(ctrl.warmup_done_ts, float) + assert ctrl.warmup_done_ts > 0 + ctrl.shutdown() + + +def test_app_controller_first_frame_ts_stamped_via_callback() -> None: + """mark_first_frame_rendered() stamps first_frame_ts once (idempotent).""" + from src.app_controller import AppController + import time + ctrl = AppController(log_to_stderr=False) + assert ctrl.first_frame_ts is None + t_before = time.time() + ctrl.mark_first_frame_rendered() + t_after = time.time() + assert isinstance(ctrl.first_frame_ts, float) + assert t_before <= ctrl.first_frame_ts <= t_after + # Second call is a no-op (idempotent) + first = ctrl.first_frame_ts + ctrl.mark_first_frame_rendered() + assert ctrl.first_frame_ts == first + ctrl.shutdown() + + +def test_app_controller_startup_timeline_returns_full_dict() -> None: + """startup_timeline() returns init_start_ts, warmup_done_ts, first_frame_ts, plus deltas.""" + from src.app_controller import AppController + ctrl = AppController(log_to_stderr=False) + ctrl.wait_for_warmup(timeout=60.0) + ctrl.mark_first_frame_rendered() + tl = ctrl.startup_timeline() + assert "init_start_ts" in tl + assert "warmup_done_ts" in tl + assert "first_frame_ts" in tl + assert "warmup_ms" in tl + assert "first_frame_after_init_ms" in tl + assert "first_frame_after_warmup_ms" in tl + assert isinstance(tl["init_start_ts"], float) + assert isinstance(tl["warmup_ms"], (float, int)) + assert tl["warmup_ms"] >= 0 + assert tl["first_frame_after_init_ms"] >= tl["warmup_ms"] + ctrl.shutdown() + + +def test_app_controller_startup_timeline_deltas_sign_correctly() -> None: + """first_frame_after_warmup_ms is the gap between first frame and warmup done.""" + from src.app_controller import AppController + ctrl = AppController(log_to_stderr=False) + ctrl.wait_for_warmup(timeout=60.0) + ctrl.mark_first_frame_rendered() + tl = ctrl.startup_timeline() + # First frame called AFTER warmup done -> positive or zero + assert tl["first_frame_after_warmup_ms"] >= 0 + # Total: first frame after init = warmup_ms + gap + assert abs(tl["first_frame_after_init_ms"] - (tl["warmup_ms"] + tl["first_frame_after_warmup_ms"])) < 0.1 + ctrl.shutdown()