WolfDavid commited on
Commit
30d0446
·
1 Parent(s): c23e6ce

feat(01-10): measure 30 warm turns against the Space and commit docs/LATENCY.md

Browse files

VOIC-05 asked for a measured number, not a predicted one. tests/e2e/test_latency_harness.py
drives the deployed Space through one throwaway warm-up, 30 typed turns over five fixed
sentences (5-36 moras, the short and long fixture texts among them) and 5 replays, reads
each turn's own performance marks (turn:dispatch -> turn:response -> turn:speech-start)
and the server's per-stage timings, computes nearest-rank p50/p95 and writes the
document with the revision SHA, hardware, DISABLE_GPU read back from the Hub, browser
and method. It asserts no threshold: its only failure is not producing a number.

Measured 2026-09-06 on c911d74 (zero-a10g, DISABLE_GPU=1): dispatch -> speech-start
p50 7107 ms / p95 10713 ms; synthesis p50 6422 ms is 90 % of the turn; replay 0 ms.
The p50 exceeds the 2.5 s re-plan trigger of 01-RESEARCH Open Question 6, which the
document says plainly - a roadmap decision, not a phase failure. The Space's CPU share
is the lever; nothing is changed here.

A loopback --space-url writes to tmp_path so a rehearsal can never overwrite the
Space's record, and the owner's Cold start / Mobile / Lip-sync sections are carried
forward verbatim on every re-run. Those three sections are placeholders for the
plan's Task 3. 01-VALIDATION.md marks the harness row green and the cold-start row
pending on the owner.

.planning/phases/01-voice-avatar-loop-skeleton/01-VALIDATION.md CHANGED
@@ -63,8 +63,8 @@ the planner MUST bind each row to a task and the executor MUST fill in Status.
63
  | VOIC-03 | Replay re-emits cached directive with **zero** network requests | E2E | `pytest tests/e2e/test_avatar_loop.py::test_replay -x` | ✅ 01-09 | ✅ green (deployed, c911d74, 2026-09-06: 0 network requests, replayCount 1, turnCount unchanged, replay→speech-start 0 ms vs 6110 ms for the turn) |
64
  | VOIC-03 | "Slower" produces measurably longer audio for the same text | E2E | `pytest tests/e2e/test_avatar_loop.py::test_slower -x` | ✅ 01-09 | ✅ green (deployed, c911d74, 2026-09-06: 5.504 s → 7.381 s, ratio 1.3411, both within one frame of the engine fixtures, synthesis_ms 11347 slow / 10239 normal, mouth sampled open to 1.0) |
65
  | VOIC-05 | "Thinking" state activates on dispatch, clears on `speech-start` | E2E | `pytest tests/e2e/test_avatar_loop.py::test_thinking_state -x` | ✅ 01-09 | ✅ green (deployed, c911d74, 2026-09-06: thinking true 0.0 ms after the click, 50 samples true until speech-start, false 70 ms after the event, headPitch 0.092 thinking vs −0.007 after) |
66
- | VOIC-05 | p50/p95 over ≥30 warm turns against the deployed Space → `docs/LATENCY.md` | harness (deployed) | `pytest tests/e2e/test_latency_harness.py --space-url=$SPACE_URL` | ❌ W0 | ⬜ pending |
67
- | VOIC-05 | Cold-start turn measured after Space pause/restart | **manual (deployed)** | record in `docs/LATENCY.md` with Space revision SHA | ❌ W0 | ⬜ pending |
68
  | SC-4 | Full loop completes with `DISABLE_GPU=1` on the Space | E2E (deployed) | `pytest tests/e2e/test_avatar_loop.py -x` against GPU-disabled Space | ✅ 01-09 | ✅ green (2026-09-06: 15 passed / 0 failed against revision `c911d74`, `DISABLE_GPU=1` read back from the Space variables in the same script; record in docs/HOSTING.md § SC-4 run record) |
69
  | SC-4 | Static guard: no `@spaces.GPU` anywhere on the turn path | unit | `pytest tests/test_no_gpu_on_turn_path.py -x` (AST scan) | ✅ 01-08 | ✅ green (3 passed, 2026-09-06; the ZeroGPU probe in app.py is carved out by name and proven unreachable from `blocks.turn`) |
70
  | DPLY-01 | Public Space returns HTTP 200 and the app shell paints | E2E (deployed) | `pytest tests/e2e/test_avatar_loop.py::test_space_reachable -x` | ✅ 01-05 | ✅ green (deployed, 2026-09-05 on 487b8cf; re-run 2026-09-06 on c911d74) |
@@ -83,7 +83,7 @@ the planner MUST bind each row to a task and the executor MUST fill in Status.
83
  - [ ] `tests/test_tts_contract.py` — VOIC-01
84
  - [x] `tests/test_no_gpu_on_turn_path.py` — SC-4 static AST scan (plan 01-08)
85
  - [x] `tests/e2e/test_avatar_loop.py` — AVTR-01, VOIC-02/03/04/05, DPLY-01/04 (plan 01-05: 5 tests; plan 01-09: 9 more, 14 functions / 15 items)
86
- - [ ] `tests/e2e/test_latency_harness.py` — VOIC-05, emits `docs/LATENCY.md`
87
  - [ ] Fixture audio — Japanese speech WAV, 30s silence, 30s café noise
88
  - [ ] Framework install — `uv add --dev pytest playwright ruff && playwright install chromium`
89
  - [ ] **Empirical spike FIRST:** deploy a Space rendering one VRM with idle motion playing one canned WAV against a hardcoded timeline. If it fails, re-plan onto the `<iframe>` + `postMessage` seam.
@@ -109,7 +109,7 @@ so every visual assertion becomes a numeric one.
109
 
110
  | Behavior | Requirement | Why Manual | Test Instructions |
111
  |---|---|---|---|
112
- | Renders in desktop Chrome **and** ≥1 mobile browser | AVTR-01 | Real mobile GPU performance and thermals can't be emulated | Load deployed Space on a real device; record device/OS/browser/FPS in `docs/LATENCY.md` |
113
  | Lip-sync looks right (visemes visibly differ, no drift over 20s) | AVTR-02 | Aesthetic judgement | Screen recording attached to phase verification |
114
  | True cold-start-from-sleep timing | VOIC-05 | Requires the Space to actually sleep (48h `gcTimeout`) | Pause/restart Space, time first turn, record with revision SHA |
115
  | LICENSES.md covers every shipped third-party asset | DPLY-04 | Legal completeness judgement | Checklist: VRM, VOICEVOX software, voice model, character, Open JTalk dict, three.js, three-vrm, transformers.js — **LICENSES.md written by plan 01-09 (2026-09-06)** with a row for each of the eight plus the ONNX Runtime and the Whisper weights, every cell filled, and a verification record; the human judgement row stays open for the phase verifier |
 
63
  | VOIC-03 | Replay re-emits cached directive with **zero** network requests | E2E | `pytest tests/e2e/test_avatar_loop.py::test_replay -x` | ✅ 01-09 | ✅ green (deployed, c911d74, 2026-09-06: 0 network requests, replayCount 1, turnCount unchanged, replay→speech-start 0 ms vs 6110 ms for the turn) |
64
  | VOIC-03 | "Slower" produces measurably longer audio for the same text | E2E | `pytest tests/e2e/test_avatar_loop.py::test_slower -x` | ✅ 01-09 | ✅ green (deployed, c911d74, 2026-09-06: 5.504 s → 7.381 s, ratio 1.3411, both within one frame of the engine fixtures, synthesis_ms 11347 slow / 10239 normal, mouth sampled open to 1.0) |
65
  | VOIC-05 | "Thinking" state activates on dispatch, clears on `speech-start` | E2E | `pytest tests/e2e/test_avatar_loop.py::test_thinking_state -x` | ✅ 01-09 | ✅ green (deployed, c911d74, 2026-09-06: thinking true 0.0 ms after the click, 50 samples true until speech-start, false 70 ms after the event, headPitch 0.092 thinking vs −0.007 after) |
66
+ | VOIC-05 | p50/p95 over ≥30 warm turns against the deployed Space → `docs/LATENCY.md` | harness (deployed) | `pytest tests/e2e/test_latency_harness.py --space-url=$SPACE_URL` | ✅ 01-10 | ✅ green (deployed, c911d74, 2026-09-06: N=30 warm turns + 5 replays, dispatch→speech-start **p50 7107 ms / p95 10713 ms** nearest-rank, synthesis p50 6422 ms = 90 % of the turn, replay p50 0 ms, DISABLE_GPU=1 read back; the harness passes by producing the number — p50 > 2.5 s fired 01-RESEARCH Open Question 6's re-plan trigger, recorded in docs/LATENCY.md, not a phase failure) |
67
+ | VOIC-05 | Cold-start turn measured after Space pause/restart | **manual (deployed)** | record in `docs/LATENCY.md` with Space revision SHA | ✅ 01-10 (table + placeholders in docs/LATENCY.md) | ⬜ pending — 01-10 Task 3, owner-gated (Pause/Restart the Space, stopwatch three times) |
68
  | SC-4 | Full loop completes with `DISABLE_GPU=1` on the Space | E2E (deployed) | `pytest tests/e2e/test_avatar_loop.py -x` against GPU-disabled Space | ✅ 01-09 | ✅ green (2026-09-06: 15 passed / 0 failed against revision `c911d74`, `DISABLE_GPU=1` read back from the Space variables in the same script; record in docs/HOSTING.md § SC-4 run record) |
69
  | SC-4 | Static guard: no `@spaces.GPU` anywhere on the turn path | unit | `pytest tests/test_no_gpu_on_turn_path.py -x` (AST scan) | ✅ 01-08 | ✅ green (3 passed, 2026-09-06; the ZeroGPU probe in app.py is carved out by name and proven unreachable from `blocks.turn`) |
70
  | DPLY-01 | Public Space returns HTTP 200 and the app shell paints | E2E (deployed) | `pytest tests/e2e/test_avatar_loop.py::test_space_reachable -x` | ✅ 01-05 | ✅ green (deployed, 2026-09-05 on 487b8cf; re-run 2026-09-06 on c911d74) |
 
83
  - [ ] `tests/test_tts_contract.py` — VOIC-01
84
  - [x] `tests/test_no_gpu_on_turn_path.py` — SC-4 static AST scan (plan 01-08)
85
  - [x] `tests/e2e/test_avatar_loop.py` — AVTR-01, VOIC-02/03/04/05, DPLY-01/04 (plan 01-05: 5 tests; plan 01-09: 9 more, 14 functions / 15 items)
86
+ - [x] `tests/e2e/test_latency_harness.py` — VOIC-05, emits `docs/LATENCY.md` (plan 01-10; first deployed run 2026-09-06 on c911d74)
87
  - [ ] Fixture audio — Japanese speech WAV, 30s silence, 30s café noise
88
  - [ ] Framework install — `uv add --dev pytest playwright ruff && playwright install chromium`
89
  - [ ] **Empirical spike FIRST:** deploy a Space rendering one VRM with idle motion playing one canned WAV against a hardcoded timeline. If it fails, re-plan onto the `<iframe>` + `postMessage` seam.
 
109
 
110
  | Behavior | Requirement | Why Manual | Test Instructions |
111
  |---|---|---|---|
112
+ | Renders in desktop Chrome **and** ≥1 mobile browser | AVTR-01 | Real mobile GPU performance and thermals can't be emulated | Load deployed Space on a real device; record device/OS/browser/FPS in `docs/LATENCY.md` — **table with placeholder row created by 01-10 Task 2; owner fills at 01-10 Task 3** |
113
  | Lip-sync looks right (visemes visibly differ, no drift over 20s) | AVTR-02 | Aesthetic judgement | Screen recording attached to phase verification |
114
  | True cold-start-from-sleep timing | VOIC-05 | Requires the Space to actually sleep (48h `gcTimeout`) | Pause/restart Space, time first turn, record with revision SHA |
115
  | LICENSES.md covers every shipped third-party asset | DPLY-04 | Legal completeness judgement | Checklist: VRM, VOICEVOX software, voice model, character, Open JTalk dict, three.js, three-vrm, transformers.js — **LICENSES.md written by plan 01-09 (2026-09-06)** with a row for each of the eight plus the ONNX Runtime and the Whisper weights, every cell filled, and a verification record; the human judgement row stays open for the phase verifier |
docs/LATENCY.md ADDED
@@ -0,0 +1,114 @@
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1
+ # Turn latency (VOIC-05)
2
+
3
+ **Measured:** 2026-09-06T04:32:30Z
4
+ **Space:** WolfDavid/japanese-learning-avatar **Revision:** `c911d74b378981e6ba0d0111eb570ed3b20927db` **URL measured:** https://wolfdavid-japanese-learning-avatar.hf.space
5
+ **Hardware:** zero-a10g (stage `RUNNING`) **DISABLE_GPU:** 1
6
+ **Browser:** Chromium 151.0.7922.34 (Playwright, headless) **Client:** Windows 11, public internet, one visitor
7
+ **Method:** N=30 warm text turns after 1 throwaway warm-up (こんにちは), 5 replay turns, five sentences of 5–36 moras in a fixed cycle (`tests/e2e/test_latency_harness.py`). Measured from the page's own `performance.mark` entries; server stages from `__debug.lastStageTimings`.
8
+ p95 computed by **nearest-rank** (the ceil(0.95·N)-th smallest observed value; p50 likewise), so no percentile is an interpolated value that was never observed.
9
+
10
+ Generated by the harness; the **Cold start**, **Mobile** and **Lip-sync** sections are the owner's and are carried forward verbatim when the harness re-runs.
11
+
12
+ ## Warm turns (N=30)
13
+
14
+ | Stage | p50 (ms) | p95 (ms) | min | max |
15
+ |---|---|---|---|---|
16
+ | dispatch -> speech-start (THE NUMBER) | 7107 | 10713 | 4589 | 10858 |
17
+ | dispatch -> response | 6829 | 10443 | 4326 | 10592 |
18
+ | server: audio_query | 1 | 2 | 1 | 2 |
19
+ | server: synthesis | 6422 | 10118 | 4134 | 10120 |
20
+ | server: timeline | 0 | 1 | 0 | 1 |
21
+ | server: encode | 0 | 1 | 0 | 1 |
22
+ | server: total | 6424 | 10121 | 4136 | 10124 |
23
+
24
+ Per sentence (dispatch -> speech-start, ms; each sentence was spoken 6 times):
25
+
26
+ | # | Sentence | Moras | p50 | min | max | synthesis p50 |
27
+ |---|---|---|---|---|---|---|
28
+ | 1 | こんにちは | 5 | 6417 | 4589 | 6706 | 5860 |
29
+ | 2 | はじめまして、よろしくお願いします。 | 17 (hand) | 8142 | 5572 | 10677 | 7510 |
30
+ | 3 | 今日はいい天気ですから、公園を散歩してから、買い物に行きました。 | 36 | 10207 | 9634 | 10858 | 9653 |
31
+ | 4 | 駅はどこですか。 | 8 (hand) | 6828 | 6674 | 7113 | 6224 |
32
+ | 5 | 日本語を勉強しています。 | 14 (hand) | 6365 | 4872 | 8437 | 5835 |
33
+
34
+ ## Replay (N=5, client-side, zero network)
35
+
36
+ | Stage | p50 (ms) | p95 (ms) | min | max |
37
+ |---|---|---|---|---|
38
+ | dispatch -> speech-start | 0 | 0 | 0 | 0 |
39
+
40
+ Replay p50 0 ms vs warm-turn p50 7107 ms: the cache is free, the round trip is the cost.
41
+
42
+ ## Cold start
43
+
44
+ | Measurement | Value | How obtained |
45
+ |---|---|---|
46
+ | Space SLEEPING -> first HTTP 200 | **PENDING - Task 3 (owner)** | Pause + Restart (or factory rebuild - say which) from Space Settings, stopwatch from page load |
47
+ | First turn after boot (synthesiser load dominates) | **PENDING - Task 3 (owner)** | first typed turn after the restart, until audible speech |
48
+ | Page load -> avatar `ready` (client-side, no backend) | this run: ready 4.2 s, first rendered frame 5.7 s (Space already RUNNING) | `wait_for_avatar_ready`; plan 01-05 recorded 4.1–8.3 s warm with tutor.vrm 3.0–6.8 s of it, 01-09 4.0–16.8 s; Space rebuild-to-RUNNING 106 s (01-05); warm wake 0.2–2.7 s |
49
+
50
+ Revision live during the cold-start test: **PENDING - Task 3 (owner)**.
51
+
52
+ ## Mobile
53
+
54
+ | Device | OS | Browser | Renders? | Observed smoothness | Push-to-talk | Turn latency |
55
+ |---|---|---|---|---|---|---|
56
+ | **PENDING - Task 3 (owner)** | | | | | | |
57
+
58
+ Open the Space on a real phone via the huggingface.co Space page, not only the direct subdomain; record device, OS version, browser version, renders / smooth-or-slideshow, warmth, whether the mic permission and push-to-talk worked, and a rough turn time.
59
+
60
+ ## Lip-sync verification (AVTR-02)
61
+
62
+ **PENDING - Task 3 (owner).** Date, sentence used (~20 s), duration, and the four judgements: (1) do あ/い/う visibly differ; (2) does the mouth close on ん, っ and pauses; (3) is the END of the sentence as well synced as the start (drift over the last third is the documented failure mode); (4) does the mouth freeze on です / した (devoiced vowels)? Plus a path or link to the screen recording.
63
+
64
+ ## Interpretation
65
+
66
+ - **p50 dispatch -> speech-start is 7107 ms** (over the ~1500 ms VOIC-05 perceived-response target; OVER the 2500 ms re-plan trigger).
67
+
68
+ > **RE-PLAN TRIGGER FIRED.** p50 7107 ms exceeds 2500 ms. Per `01-RESEARCH.md` Open Question 6 - *"treat p50 > ~2.5 s as a re-plan trigger, not a phase failure"* - this is a decision for the roadmap, not a failing test: the criterion for Phase 1 is *"p50/p95 measured and recorded"*, which this file is.
69
+ - **What dominates:** VOICEVOX synthesis on the Space's CPU - server `synthesis_ms` p50 6422 ms is 90 % of the p50 turn; `audio_query` (1.4 ms), `timeline` (0.36 ms) and `encode` (0.17 ms) are noise. Network + Gradio round trip above the server total: 405 ms at p50; browser decode + schedule after the response: 278 ms at p50.
70
+ - **Cheapest improvement (recorded, NOT implemented in Phase 1):** the same sentence synthesises 3–6x faster on a developer laptop than on the Space (plan 01-09), so the container's CPU share is the lever - check `cpu_num_threads` on the Space's `Synthesizer` and whether the ZeroGPU container's CPU allocation is the ceiling; beyond that, VOICEVOX CORE 0.17's streaming synthesis would let speech start before the whole utterance is rendered, and per-sentence synthesis of long replies would bound the first-sample latency by the first sentence rather than the whole reply.
71
+
72
+ ## Notes
73
+
74
+ - Phase 1 has no LLM. These numbers are NOT predictive of Phase 3, which adds one.
75
+ - Space sleeps after 48 h (gcTimeout 172800), so a cold start is the default first-visit experience.
76
+ - Numbers live in git because Space disk is ephemeral. Continuous telemetry is deliberately deferred to Phase 4/6, which owns the privacy story.
77
+ - Headless Chromium renders through SwiftShader on the client; the client-side decode + schedule share above is therefore an upper bound on what a GPU-rendered visitor sees.
78
+
79
+ ## Raw samples (dispatch -> speech-start, ms, in run order)
80
+
81
+ | Turn | Sentence # | dispatch->speech | dispatch->response | synthesis | lastTurnMs |
82
+ |---|---|---|---|---|---|
83
+ | 1 | 1 | 6538 | 6262 | 5997 | 6538 |
84
+ | 2 | 2 | 9639 | 9361 | 8902 | 9639 |
85
+ | 3 | 3 | 9661 | 9390 | 9165 | 9661 |
86
+ | 4 | 4 | 6674 | 6401 | 6117 | 6674 |
87
+ | 5 | 5 | 7722 | 7441 | 7100 | 7722 |
88
+ | 6 | 1 | 4589 | 4326 | 4134 | 4589 |
89
+ | 7 | 2 | 10677 | 10406 | 10099 | 10677 |
90
+ | 8 | 3 | 10713 | 10443 | 10120 | 10713 |
91
+ | 9 | 4 | 7113 | 6836 | 6503 | 7113 |
92
+ | 10 | 5 | 6365 | 6086 | 5787 | 6365 |
93
+ | 11 | 1 | 6417 | 6144 | 5860 | 6417 |
94
+ | 12 | 2 | 8740 | 8460 | 8201 | 8740 |
95
+ | 13 | 3 | 10858 | 10592 | 10118 | 10858 |
96
+ | 14 | 4 | 7107 | 6829 | 6422 | 7107 |
97
+ | 15 | 5 | 8437 | 8157 | 7936 | 8437 |
98
+ | 16 | 1 | 6662 | 6390 | 6097 | 6662 |
99
+ | 17 | 2 | 7552 | 7282 | 6998 | 7553 |
100
+ | 18 | 3 | 9634 | 9360 | 9083 | 9634 |
101
+ | 19 | 4 | 7113 | 6847 | 6646 | 7113 |
102
+ | 20 | 5 | 6635 | 6364 | 6089 | 6635 |
103
+ | 21 | 1 | 6706 | 6434 | 6081 | 6706 |
104
+ | 22 | 2 | 8142 | 7868 | 7510 | 8142 |
105
+ | 23 | 3 | 10552 | 10277 | 9963 | 10552 |
106
+ | 24 | 4 | 6828 | 6552 | 6127 | 6828 |
107
+ | 25 | 5 | 4872 | 4601 | 4284 | 4872 |
108
+ | 26 | 1 | 6188 | 5912 | 5713 | 6188 |
109
+ | 27 | 2 | 5572 | 5297 | 4900 | 5572 |
110
+ | 28 | 3 | 10207 | 9924 | 9653 | 10207 |
111
+ | 29 | 4 | 6775 | 6505 | 6224 | 6775 |
112
+ | 30 | 5 | 6337 | 6068 | 5835 | 6337 |
113
+
114
+ Replays (dispatch -> speech-start, ms): 0, 0, 0, 0, 0
tests/e2e/test_latency_harness.py ADDED
@@ -0,0 +1,527 @@
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1
+ """VOIC-05's measurement: N warm turns against the deployed Space, written to docs/LATENCY.md.
2
+
3
+ This is a HARNESS, not an assertion suite. Its job is to produce a number with enough
4
+ context to reproduce it; the only thing it fails on is not being able to produce one.
5
+ 01-RESEARCH.md is emphatic that a predicted latency must not become an acceptance
6
+ criterion, so there is no threshold here. If the p50 exceeds the ~2.5 s re-plan trigger
7
+ (Open Question 6) the harness says so loudly, in the test output and in the document,
8
+ and still passes.
9
+
10
+ The numbers live in git (docs/LATENCY.md) because Space disk is ephemeral and Phase 4
11
+ owns persistence; that is option 1 of the three RESEARCH lists, chosen deliberately over
12
+ a SQLite file on the Space and over a CommitScheduler telemetry stream.
13
+
14
+ Method, fixed so the run is reproducible: load the Space, wait for the first rendered
15
+ frame, one throwaway turn to warm the synthesiser, then N=30 typed turns cycling a fixed
16
+ list of five sentences in a fixed order (the ``short`` and ``long`` fixture texts among
17
+ them, so the sample is not all one size), then 5 replays. Per turn the page's own
18
+ performance marks are read (``turn:dispatch`` -> ``turn:response`` ->
19
+ ``turn:speech-start``) alongside the server's per-stage timings. Percentiles are
20
+ nearest-rank: with N=30 the p95 method matters, and nearest-rank never invents a value
21
+ that was not observed.
22
+
23
+ Run::
24
+
25
+ .venv/Scripts/python.exe -m pytest tests/e2e/test_latency_harness.py -q \
26
+ --space-url https://wolfdavid-japanese-learning-avatar.hf.space
27
+
28
+ A loopback ``--space-url`` (a local rehearsal) writes to pytest's tmp_path instead of
29
+ docs/LATENCY.md, so a developer machine's numbers can never overwrite the Space's.
30
+ """
31
+
32
+ from __future__ import annotations
33
+
34
+ import math
35
+ import os
36
+ import platform
37
+ import re
38
+ import time
39
+ from datetime import UTC, datetime
40
+ from pathlib import Path
41
+ from urllib.parse import urlparse
42
+
43
+ import pytest
44
+
45
+ from tests.e2e.test_avatar_loop import _controls_rearmed, _text_turn, read_debug
46
+
47
+ pytestmark = [pytest.mark.deployed, pytest.mark.slow]
48
+
49
+ REPO_ROOT = Path(__file__).resolve().parent.parent.parent
50
+ LATENCY_MD = REPO_ROOT / "docs" / "LATENCY.md"
51
+ SPACE_REPO = "WolfDavid/japanese-learning-avatar"
52
+
53
+ WARM_TURNS = 30
54
+ REPLAY_TURNS = 5
55
+ # Fixed list, fixed order. Indexes 0 and 2 are replaced at run time by the short and long
56
+ # fixture texts from tests/fixtures/synth_meta.json (5 and 36 moras), and the harness
57
+ # asserts they are what this list says, so a fixture edit cannot silently change the
58
+ # sample. The other three span the range between.
59
+ SENTENCES = (
60
+ "こんにちは",
61
+ "はじめまして、よろしくお願いします。",
62
+ "今日はいい天気ですから、公園を散歩してから、買い物に行きました。",
63
+ "駅はどこですか。",
64
+ "日本語を勉強しています。",
65
+ )
66
+ WARMUP_TEXT = "こんにちは"
67
+ # Mora counts for the three non-fixture sentences, counted by hand (the engine's own
68
+ # count for the fixture sentences comes from synth_meta.json at run time).
69
+ HAND_COUNTED_MORAS = {1: "17 (hand)", 3: "8 (hand)", 4: "14 (hand)"}
70
+
71
+ # The Space's CPU synthesises the 36-mora sentence in ~10 s (plan 01-09); the bounds are
72
+ # wide because a slow turn is a data point here, not a failure.
73
+ START_TIMEOUT_MS = 120_000
74
+ END_TIMEOUT_MS = 90_000
75
+ REARM_TIMEOUT_MS = 90_000
76
+ REPLAY_START_TIMEOUT_MS = 10_000
77
+
78
+ REPLAN_TRIGGER_MS = 2_500
79
+ VOIC05_TARGET_MS = 1_500
80
+
81
+ STAGE_KEYS = ("audio_query_ms", "synthesis_ms", "timeline_ms", "encode_ms", "server_total_ms")
82
+
83
+ # The last occurrence of each turn mark. Marks accumulate across turns, so the latest of
84
+ # each is this turn's, read after its speech-end.
85
+ TURN_MARKS = """
86
+ () => {
87
+ const last = (name) => {
88
+ const e = performance.getEntriesByName(name, 'mark');
89
+ return e.length ? e[e.length - 1].startTime : null;
90
+ };
91
+ return {
92
+ dispatch: last('turn:dispatch'),
93
+ response: last('turn:response'),
94
+ speechStart: last('turn:speech-start'),
95
+ replayDispatch: last('replay:dispatch'),
96
+ replaySpeechStart: last('replay:speech-start'),
97
+ };
98
+ }
99
+ """
100
+
101
+ # Sections of docs/LATENCY.md that a HUMAN fills (plan 01-10 Task 3). When the file
102
+ # already has them, they are carried forward verbatim so re-running the harness can
103
+ # never erase the owner's cold-start, mobile or lip-sync answers.
104
+ HUMAN_SECTIONS = ("Cold start", "Mobile", "Lip-sync verification (AVTR-02)")
105
+
106
+
107
+ def nearest_rank(values: list[float], percentile: float) -> float:
108
+ """Nearest-rank percentile: the ceil(P/100 * N)-th smallest observed value."""
109
+ ordered = sorted(values)
110
+ rank = max(1, math.ceil(percentile / 100 * len(ordered)))
111
+ return ordered[rank - 1]
112
+
113
+
114
+ def summarise(values: list[float]) -> dict[str, float]:
115
+ return {
116
+ "p50": nearest_rank(values, 50),
117
+ "p95": nearest_rank(values, 95),
118
+ "min": min(values),
119
+ "max": max(values),
120
+ "n": len(values),
121
+ }
122
+
123
+
124
+ def is_public_space(space_url: str) -> bool:
125
+ host = urlparse(space_url).hostname or ""
126
+ return host not in {"127.0.0.1", "localhost", "::1"}
127
+
128
+
129
+ def hub_metadata() -> dict[str, str]:
130
+ """Revision SHA, hardware and stage from the Hub; DISABLE_GPU if a token allows."""
131
+ meta = {
132
+ "sha": "unavailable (Hub API not reachable)",
133
+ "hardware": "unavailable",
134
+ "stage": "unavailable",
135
+ "disable_gpu": "not read (no token)",
136
+ }
137
+ try:
138
+ from huggingface_hub import HfApi
139
+
140
+ api = HfApi()
141
+ info = api.space_info(SPACE_REPO)
142
+ meta["sha"] = info.sha or meta["sha"]
143
+ runtime = getattr(info, "runtime", None)
144
+ if runtime is not None:
145
+ hw = getattr(runtime, "hardware", None)
146
+ meta["hardware"] = str(
147
+ getattr(hw, "current", None) or getattr(hw, "requested", None) or hw
148
+ )
149
+ meta["stage"] = str(getattr(runtime, "stage", "unavailable"))
150
+ try:
151
+ variables = api.get_space_variables(SPACE_REPO)
152
+ meta["disable_gpu"] = str(variables["DISABLE_GPU"].value)
153
+ except Exception as err: # noqa: BLE001 - a missing token is a fact to record
154
+ meta["disable_gpu"] = f"not read ({type(err).__name__})"
155
+ except Exception as err: # noqa: BLE001 - recorded, not fatal
156
+ meta["sha"] = f"unavailable ({type(err).__name__})"
157
+ return meta
158
+
159
+
160
+ def existing_sections(path: Path) -> dict[str, str]:
161
+ """``heading -> body`` for every ``## `` section of an existing document."""
162
+ if not path.exists():
163
+ return {}
164
+ text = path.read_text(encoding="utf-8")
165
+ parts = re.split(r"^## ", text, flags=re.M)
166
+ sections: dict[str, str] = {}
167
+ for part in parts[1:]:
168
+ heading, _, body = part.partition("\n")
169
+ sections[heading.strip()] = body.rstrip("\n")
170
+ return sections
171
+
172
+
173
+ def row(label: str, s: dict[str, float]) -> str:
174
+ return f"| {label} | {s['p50']:.0f} | {s['p95']:.0f} | {s['min']:.0f} | {s['max']:.0f} |"
175
+
176
+
177
+ def render_document(
178
+ *,
179
+ measured_at: str,
180
+ space_url: str,
181
+ meta: dict[str, str],
182
+ browser_version: str,
183
+ client: str,
184
+ load: dict[str, float],
185
+ warm: list[dict],
186
+ replays: list[dict],
187
+ carried: dict[str, str],
188
+ ) -> tuple[str, dict[str, dict[str, float]]]:
189
+ stats = {
190
+ "speech": summarise([t["dispatch_to_speech_ms"] for t in warm]),
191
+ "response": summarise([t["dispatch_to_response_ms"] for t in warm]),
192
+ "replay": summarise([r["dispatch_to_speech_ms"] for r in replays]),
193
+ }
194
+ for key in STAGE_KEYS:
195
+ stats[key] = summarise([t["timings"][key] for t in warm])
196
+ p50 = stats["speech"]["p50"]
197
+ synth_share = stats["synthesis_ms"]["p50"] / p50 * 100 if p50 else 0.0
198
+ decode_ms = stats["speech"]["p50"] - stats["response"]["p50"]
199
+
200
+ trigger_fired = p50 > REPLAN_TRIGGER_MS
201
+ replay_lower = stats["replay"]["p50"] < p50
202
+
203
+ lines = [
204
+ "# Turn latency (VOIC-05)",
205
+ "",
206
+ f"**Measured:** {measured_at} ",
207
+ f"**Space:** {SPACE_REPO} **Revision:** `{meta['sha']}` "
208
+ f"**URL measured:** {space_url} ",
209
+ f"**Hardware:** {meta['hardware']} (stage `{meta['stage']}`) "
210
+ f"**DISABLE_GPU:** {meta['disable_gpu']} ",
211
+ f"**Browser:** Chromium {browser_version} (Playwright, headless) **Client:** {client} ",
212
+ f"**Method:** N={len(warm)} warm text turns after 1 throwaway warm-up "
213
+ f"({WARMUP_TEXT}), {len(replays)} replay turns, five sentences of 5–36 moras in a fixed "
214
+ "cycle (`tests/e2e/test_latency_harness.py`). Measured from the page's own "
215
+ "`performance.mark` entries; server stages from `__debug.lastStageTimings`. ",
216
+ "p95 computed by **nearest-rank** (the ceil(0.95·N)-th smallest observed value; "
217
+ "p50 likewise), so no percentile is an interpolated value that was never observed.",
218
+ "",
219
+ "Generated by the harness; the **Cold start**, **Mobile** and **Lip-sync** sections "
220
+ "are the owner's and are carried forward verbatim when the harness re-runs.",
221
+ "",
222
+ f"## Warm turns (N={len(warm)})",
223
+ "",
224
+ "| Stage | p50 (ms) | p95 (ms) | min | max |",
225
+ "|---|---|---|---|---|",
226
+ row("dispatch -> speech-start (THE NUMBER)", stats["speech"]),
227
+ row("dispatch -> response", stats["response"]),
228
+ row("server: audio_query", stats["audio_query_ms"]),
229
+ row("server: synthesis", stats["synthesis_ms"]),
230
+ row("server: timeline", stats["timeline_ms"]),
231
+ row("server: encode", stats["encode_ms"]),
232
+ row("server: total", stats["server_total_ms"]),
233
+ "",
234
+ "Per sentence (dispatch -> speech-start, ms; each sentence was spoken "
235
+ f"{len(warm) // len(SENTENCES)} times):",
236
+ "",
237
+ "| # | Sentence | Moras | p50 | min | max | synthesis p50 |",
238
+ "|---|---|---|---|---|---|---|",
239
+ ]
240
+ for idx, sentence in enumerate(SENTENCES):
241
+ mine = [t for t in warm if t["sentence_index"] == idx]
242
+ if not mine:
243
+ continue
244
+ s = summarise([t["dispatch_to_speech_ms"] for t in mine])
245
+ synth = summarise([t["timings"]["synthesis_ms"] for t in mine])
246
+ moras = mine[0].get("moras", "")
247
+ lines.append(
248
+ f"| {idx + 1} | {sentence} | {moras} | {s['p50']:.0f} | {s['min']:.0f} | "
249
+ f"{s['max']:.0f} | {synth['p50']:.0f} |"
250
+ )
251
+
252
+ lines += [
253
+ "",
254
+ f"## Replay (N={len(replays)}, client-side, zero network)",
255
+ "",
256
+ "| Stage | p50 (ms) | p95 (ms) | min | max |",
257
+ "|---|---|---|---|---|",
258
+ row("dispatch -> speech-start", stats["replay"]),
259
+ "",
260
+ (
261
+ f"Replay p50 {stats['replay']['p50']:.0f} ms vs warm-turn p50 {p50:.0f} ms: "
262
+ + (
263
+ "the cache is free, the round trip is the cost."
264
+ if replay_lower
265
+ else "**replay is NOT faster than a turn - a real finding, recorded, not hidden.**"
266
+ )
267
+ ),
268
+ "",
269
+ ]
270
+
271
+ # Human-owned sections: carried forward if the owner has filled them, else templates.
272
+ cold_default = "\n".join(
273
+ [
274
+ "",
275
+ "| Measurement | Value | How obtained |",
276
+ "|---|---|---|",
277
+ "| Space SLEEPING -> first HTTP 200 | **PENDING - Task 3 (owner)** | Pause + Restart "
278
+ "(or factory rebuild - say which) from Space Settings, stopwatch from page load |",
279
+ "| First turn after boot (synthesiser load dominates) | **PENDING - Task 3 (owner)** | "
280
+ "first typed turn after the restart, until audible speech |",
281
+ f"| Page load -> avatar `ready` (client-side, no backend) | this run: ready "
282
+ f"{load['ready_seconds']:.1f} s, first rendered frame "
283
+ f"{load['first_frame_seconds']:.1f} s"
284
+ " (Space already RUNNING) | `wait_for_avatar_ready`; plan 01-05 recorded 4.1–8.3 s "
285
+ "warm with tutor.vrm 3.0–6.8 s of it, 01-09 4.0–16.8 s; Space rebuild-to-RUNNING "
286
+ "106 s (01-05); warm wake 0.2–2.7 s |",
287
+ "",
288
+ "Revision live during the cold-start test: **PENDING - Task 3 (owner)**.",
289
+ ]
290
+ )
291
+ mobile_default = "\n".join(
292
+ [
293
+ "",
294
+ "| Device | OS | Browser | Renders? | Observed smoothness | Push-to-talk | "
295
+ "Turn latency |",
296
+ "|---|---|---|---|---|---|---|",
297
+ "| **PENDING - Task 3 (owner)** | | | | | | |",
298
+ "",
299
+ "Open the Space on a real phone via the huggingface.co Space page, not only the direct "
300
+ "subdomain; record device, OS version, browser version, renders / smooth-or-slideshow, "
301
+ "warmth, whether the mic permission and push-to-talk worked, and a rough turn time.",
302
+ ]
303
+ )
304
+ lipsync_default = "\n".join(
305
+ [
306
+ "",
307
+ "**PENDING - Task 3 (owner).** Date, sentence used (~20 s), duration, and the four "
308
+ "judgements: (1) do あ/い/う visibly differ; (2) does the mouth close on ん, っ and "
309
+ "pauses; (3) is the END of the sentence as well synced as the start (drift over the "
310
+ "last third is the documented failure mode); (4) does the mouth freeze on です / した "
311
+ "(devoiced vowels)? Plus a path or link to the screen recording.",
312
+ ]
313
+ )
314
+ defaults = {
315
+ "Cold start": cold_default,
316
+ "Mobile": mobile_default,
317
+ "Lip-sync verification (AVTR-02)": lipsync_default,
318
+ }
319
+ for heading in HUMAN_SECTIONS:
320
+ body = carried.get(heading)
321
+ if body is None or "PENDING - Task 3" in body:
322
+ body = defaults[heading]
323
+ lines += [f"## {heading}", body, ""]
324
+
325
+ under_target = p50 < VOIC05_TARGET_MS
326
+ lines += [
327
+ "## Interpretation",
328
+ "",
329
+ f"- **p50 dispatch -> speech-start is {p50:.0f} ms** "
330
+ f"({'under' if under_target else 'over'} the ~{VOIC05_TARGET_MS} ms VOIC-05 perceived-"
331
+ f"response target; {'under' if not trigger_fired else 'OVER'} the {REPLAN_TRIGGER_MS} ms "
332
+ "re-plan trigger).",
333
+ ]
334
+ if trigger_fired:
335
+ lines += [
336
+ "",
337
+ f"> **RE-PLAN TRIGGER FIRED.** p50 {p50:.0f} ms exceeds {REPLAN_TRIGGER_MS} ms. Per "
338
+ '`01-RESEARCH.md` Open Question 6 - *"treat p50 > ~2.5 s as a re-plan trigger, not a '
339
+ 'phase failure"* - this is a decision for the roadmap, not a failing test: the '
340
+ 'criterion for Phase 1 is *"p50/p95 measured and recorded"*, which this file is.',
341
+ ]
342
+ lines += [
343
+ f"- **What dominates:** VOICEVOX synthesis on the Space's CPU - server `synthesis_ms` p50 "
344
+ f"{stats['synthesis_ms']['p50']:.0f} ms is {synth_share:.0f} % of the p50 turn; "
345
+ f"`audio_query` ({stats['audio_query_ms']['p50']:.1f} ms), `timeline` "
346
+ f"({stats['timeline_ms']['p50']:.2f} ms) and `encode` ({stats['encode_ms']['p50']:.2f} ms) "
347
+ "are noise. Network + Gradio round trip above the server total: "
348
+ f"{stats['response']['p50'] - stats['server_total_ms']['p50']:.0f} ms at p50; browser "
349
+ f"decode + schedule after the response: {decode_ms:.0f} ms at p50.",
350
+ "- **Cheapest improvement (recorded, NOT implemented in Phase 1):** the same sentence "
351
+ "synthesises 3–6x faster on a developer laptop than on the Space (plan 01-09), so the "
352
+ "container's CPU share is the lever - check `cpu_num_threads` on the Space's "
353
+ "`Synthesizer` and whether the ZeroGPU container's CPU allocation is the ceiling; "
354
+ "beyond that, VOICEVOX CORE 0.17's streaming synthesis would let speech start before the "
355
+ "whole utterance is rendered, and per-sentence synthesis of long replies would bound the "
356
+ "first-sample latency by the first sentence rather than the whole reply.",
357
+ "",
358
+ "## Notes",
359
+ "",
360
+ "- Phase 1 has no LLM. These numbers are NOT predictive of Phase 3, which adds one.",
361
+ "- Space sleeps after 48 h (gcTimeout 172800), so a cold start is the default first-visit "
362
+ "experience.",
363
+ "- Numbers live in git because Space disk is ephemeral. Continuous telemetry is "
364
+ "deliberately deferred to Phase 4/6, which owns the privacy story.",
365
+ "- Headless Chromium renders through SwiftShader on the client; the client-side decode + "
366
+ "schedule share above is therefore an upper bound on what a GPU-rendered visitor sees.",
367
+ "",
368
+ "## Raw samples (dispatch -> speech-start, ms, in run order)",
369
+ "",
370
+ "| Turn | Sentence # | dispatch->speech | dispatch->response | synthesis | lastTurnMs |",
371
+ "|---|---|---|---|---|---|",
372
+ ]
373
+ for i, t in enumerate(warm, start=1):
374
+ lines.append(
375
+ f"| {i} | {t['sentence_index'] + 1} | {t['dispatch_to_speech_ms']:.0f} | "
376
+ f"{t['dispatch_to_response_ms']:.0f} | {t['timings']['synthesis_ms']:.0f} | "
377
+ f"{t['last_turn_ms']} |"
378
+ )
379
+ lines += [
380
+ "",
381
+ "Replays (dispatch -> speech-start, ms): "
382
+ + ", ".join(f"{r['dispatch_to_speech_ms']:.0f}" for r in replays),
383
+ "",
384
+ ]
385
+ return "\n".join(lines), stats
386
+
387
+
388
+ def _measure_turn(page, speech_events, text: str, index: int, moras: str) -> dict:
389
+ turn = _text_turn(
390
+ page,
391
+ speech_events,
392
+ text,
393
+ start_timeout_ms=START_TIMEOUT_MS,
394
+ end_timeout_ms=END_TIMEOUT_MS,
395
+ )
396
+ marks = page.evaluate(TURN_MARKS)
397
+ debug = read_debug(page)
398
+ assert marks["dispatch"] is not None and marks["speechStart"] is not None, marks
399
+ assert marks["dispatch"] < marks["response"] < marks["speechStart"], marks
400
+ timings = debug["lastStageTimings"]
401
+ assert timings and all(k in timings for k in STAGE_KEYS), timings
402
+ _controls_rearmed(page, timeout_ms=REARM_TIMEOUT_MS)
403
+ return {
404
+ "sentence_index": index,
405
+ "text": text,
406
+ "moras": moras,
407
+ "dispatch_to_speech_ms": marks["speechStart"] - marks["dispatch"],
408
+ "dispatch_to_response_ms": marks["response"] - marks["dispatch"],
409
+ "last_turn_ms": debug["lastTurnMs"],
410
+ "timings": {k: float(timings[k]) for k in STAGE_KEYS},
411
+ "audio_duration_s": turn["duration"],
412
+ "wall_speech_start_s": turn["speech_start_seconds"],
413
+ }
414
+
415
+
416
+ def _measure_replay(page, speech_events) -> dict:
417
+ before = len(speech_events.named(page, "speech-end"))
418
+ page.click("#replay-button")
419
+ speech_events.wait_for(
420
+ page, "speech-start", timeout_ms=REPLAY_START_TIMEOUT_MS, at_least=before + 1
421
+ )
422
+ speech_events.wait_for(page, "speech-end", timeout_ms=END_TIMEOUT_MS, at_least=before + 1)
423
+ marks = page.evaluate(TURN_MARKS)
424
+ debug = read_debug(page)
425
+ assert marks["replayDispatch"] is not None and marks["replaySpeechStart"] is not None, marks
426
+ _controls_rearmed(page, timeout_ms=REARM_TIMEOUT_MS)
427
+ return {
428
+ "dispatch_to_speech_ms": marks["replaySpeechStart"] - marks["replayDispatch"],
429
+ "last_replay_ms": debug["lastReplayMs"],
430
+ }
431
+
432
+
433
+ @pytest.mark.deployed
434
+ @pytest.mark.slow
435
+ def test_measure_warm_turns(
436
+ page, browser, space_url, synth_meta, speech_events, wait_for_avatar_ready, tmp_path
437
+ ):
438
+ """Produce docs/LATENCY.md. Fails only if a number cannot be produced."""
439
+ short, long = synth_meta["cases"]["short"], synth_meta["cases"]["long"]
440
+ assert SENTENCES[0] == short["text"] and SENTENCES[2] == long["text"], (
441
+ "the fixed sentence list no longer matches the fixture texts"
442
+ )
443
+ moras = {0: str(short["mora_count"]), 2: str(long["mora_count"]), **HAND_COUNTED_MORAS}
444
+
445
+ public = is_public_space(space_url)
446
+ out = LATENCY_MD if public else tmp_path / "LATENCY.md"
447
+ # A local rehearsal may shorten the loop to prove the harness itself; the committed
448
+ # document is always the full N, because the override is ignored for a public URL.
449
+ turns = WARM_TURNS if public else int(os.environ.get("LATENCY_TURNS", WARM_TURNS))
450
+ carried = existing_sections(LATENCY_MD)
451
+ measured_at = datetime.now(UTC).strftime("%Y-%m-%dT%H:%M:%SZ")
452
+ meta = (
453
+ hub_metadata()
454
+ if public
455
+ else {
456
+ "sha": "local rehearsal (not the Space)",
457
+ "hardware": "developer machine",
458
+ "stage": "local",
459
+ "disable_gpu": "1 (local env)",
460
+ }
461
+ )
462
+
463
+ speech_events.install(page)
464
+ load = wait_for_avatar_ready(page, space_url)
465
+ print(
466
+ f"\n[latency] ready {load['ready_seconds']:.1f}s, "
467
+ f"first frame {load['first_frame_seconds']:.1f}s"
468
+ )
469
+
470
+ warmup = _measure_turn(page, speech_events, WARMUP_TEXT, 0, moras[0])
471
+ print(f"[latency] warm-up turn (discarded): {warmup['dispatch_to_speech_ms']:.0f} ms")
472
+
473
+ t0 = time.monotonic()
474
+ warm: list[dict] = []
475
+ for i in range(turns):
476
+ index = i % len(SENTENCES)
477
+ sample = _measure_turn(page, speech_events, SENTENCES[index], index, moras.get(index, ""))
478
+ warm.append(sample)
479
+ print(
480
+ f"[latency] turn {i + 1:2d}/{turns} s{index + 1}: "
481
+ f"{sample['dispatch_to_speech_ms']:.0f} ms to speech "
482
+ f"(response {sample['dispatch_to_response_ms']:.0f}, "
483
+ f"synthesis {sample['timings']['synthesis_ms']:.0f}, "
484
+ f"lastTurnMs {sample['last_turn_ms']})"
485
+ )
486
+ replays = [_measure_replay(page, speech_events) for _ in range(REPLAY_TURNS)]
487
+ print(
488
+ f"[latency] replays: {[round(r['dispatch_to_speech_ms']) for r in replays]} ms; "
489
+ f"{turns} turns + {REPLAY_TURNS} replays in {time.monotonic() - t0:.0f}s"
490
+ )
491
+
492
+ document, stats = render_document(
493
+ measured_at=measured_at,
494
+ space_url=space_url,
495
+ meta=meta,
496
+ browser_version=browser.version,
497
+ client=f"{platform.system()} {platform.release()}, public internet, one visitor",
498
+ load=load,
499
+ warm=warm,
500
+ replays=replays,
501
+ carried=carried,
502
+ )
503
+ out.parent.mkdir(parents=True, exist_ok=True)
504
+ out.write_text(document, encoding="utf-8", newline="\n")
505
+
506
+ p50, p95 = stats["speech"]["p50"], stats["speech"]["p95"]
507
+ print(
508
+ f"\n[latency] ===== dispatch -> speech-start: p50 {p50:.0f} ms, p95 {p95:.0f} ms "
509
+ f"(N={len(warm)}, nearest-rank); replay p50 {stats['replay']['p50']:.0f} ms; "
510
+ f"synthesis p50 {stats['synthesis_ms']['p50']:.0f} ms; revision {meta['sha']} =====\n"
511
+ f"[latency] written to {out}"
512
+ )
513
+ if p50 > REPLAN_TRIGGER_MS:
514
+ print(
515
+ f"[latency] WARNING: p50 {p50:.0f} ms exceeds the {REPLAN_TRIGGER_MS} ms re-plan "
516
+ "trigger (01-RESEARCH.md Open Question 6). This is a re-plan trigger, not a phase "
517
+ "failure; recorded in the document."
518
+ )
519
+ if stats["replay"]["p50"] >= p50:
520
+ print(
521
+ "[latency] NOTE: replay p50 is not lower than the warm-turn p50 - "
522
+ "recorded as a finding."
523
+ )
524
+
525
+ # The harness must always be able to say it produced the number.
526
+ assert len(warm) == turns and len(replays) == REPLAY_TURNS
527
+ assert out.exists() and "p95" in document and "THE NUMBER" in document