feat(startup): first-frame detection + startup_timeline API
Adds per-AppController startup timing instrumentation to answer 'did the warmup block the first frame?' AppController.__init__ records _init_start_ts at entry (cold-start anchor). WarmupManager.on_complete callback stamps _warmup_done_ts. App.render_main_interface (gui_2.py) calls mark_first_frame_rendered() on its first call, which stamps _first_frame_ts and logs the timeline. New public API on AppController: - init_start_ts (property): float - warmup_done_ts (property): Optional[float] - first_frame_ts (property): Optional[float] - mark_first_frame_rendered(ts=None): idempotent; logs to stderr - startup_timeline() -> dict with all timestamps + precomputed deltas: warmup_ms, first_frame_after_init_ms, first_frame_after_warmup_ms Stderr log on warmup done: [startup] warmup done in 1186.2ms (first frame rendered Nms BEFORE/AFTER) Stderr log on first frame: [startup] first frame at Xms after init (warmup took Yms) (rendered Zms BEFORE/AFTER warmup done) Hook API: - GET /api/startup_timeline - ApiHookClient.get_startup_timeline() -> dict 5 new tests in test_warmup_canaries.py covering all the new methods. All 18 canary tests + 10 api_hooks tests + 6 gui_indicator tests pass. Script scripts/apply_startup_timeline.py is included as a reference for the multi-edit pattern (the proper MCP-equivalent tools will be added later per the edit_workflow doc).
This commit is contained in:
@@ -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()
|
||||
|
||||
Reference in New Issue
Block a user