G0: baseline latency do xong - gate G2 mo, drift bridge -0.5% phat hien

2026-08-28 12:03:13 +07:00
parent ebe17d902b
commit d78af9304f
3 changed files with 263 additions and 3 deletions
@@ -64,9 +64,9 @@ Giữ nguyên SHM `FxRealtimeIPC` làm ranh giới (không đổi Python/JS tran
 ## 4. Giai đoạn (mỗi giai đoạn: test trước, implement tối thiểu, probe pass)

 ### G0 — Baseline đo (không code engine, làm TRƯỚC khi quyết định)
- [ ] Đo lại latency path chính xác: log `fx_play_first` timestamp vs WebAudio output actual; ghi FILL/CAP thật dưới tải GUI mở.
- [ ] Đo phân phối jitter round-trip WS→Python→SHM→bridge→return ≥10k block: mean, σ, p99, min/max. Gate G2: σ nhỏ → PDC mẫu có ý nghĩa; σ lớn → giảm jitter trước (relay WS→SHM trong bridge, Python chỉ control).
- [ ] Với mỗi VST3 trong master chain, ghi `getLatencySamples()` (qua host hiện tại nếu có API) — lập bảng plugin → latency.
+- [x] Đo lại latency path chính xác: log `fx_play_first` timestamp vs WebAudio output actual; ghi FILL/CAP thật dưới tải GUI mở.
+- [x] Đo phân phối jitter round-trip WS→Python→SHM→bridge→return ≥10k block: mean, σ, p99, min/max. Gate G2: σ nhỏ → PDC mẫu có ý nghĩa; σ lớn → giảm jitter trước (relay WS→SHM trong bridge, Python chỉ control).
+- [x] Với mỗi VST3 trong master chain, ghi `getLatencySamples()` (qua host hiện tại nếu có API) — lập bảng plugin → latency.
 - Done khi: bảng latency từng plugin + tổng chain thực đo, xác nhận ~0.22s gồm gì.

 ### G1 — JUCE engine đọc/ghi SHM, chain rỗng (POC)
@@ -0,0 +1,104 @@
+# G0 — Baseline đo latency (kết quả)
+
+Ngày: 2026-08-27. Probe: `native_bridge/debug/g0_latency_probe.py` (chạy với
+`timeBeginPeriod(1)`, 10k block/config, pipeline thật Python→SHM→fx_vst_bridge→SHM).
+Log: `native_bridge/debug/g0_probe_run_full.log`.
+
+## 1. Bảng latency plugin (getLatencySamples, @48kHz)
+
+| Plugin | getLatencySamples | ms @48k | Ghi chú |
+|---|---|---|---|
+| Sonible pureComp | 2108 | 43.9 | báo latency thật (lookahead) |
+| iZotope Ozone 11 | 0 | 0 | không báo latency (realtime mode) |
+| empty (passthrough) | — | — | chain rỗng |
+
+Nguồn: probe `plugin_latency` + log app thật `fxrt_bridge.log`
+(`[RenderFx] STEP getLatencySamples = 2108/0`).
+
+## 2. Jitter round-trip (10k block, 53.3s/config)
+
+Round-trip = thời gian từ lúc probe gọi `write_input(block j)` đến lúc nhận
+`read_output()` block j (FIFO theo index). Đã sửa pacing probe bằng
+`timeBeginPeriod(1)` (bridge C++ đã gọi — `RealtimeFxLoop.cpp:160`); lần chạy
+trước thiếu nó → Sleep 15.6ms granularity → pump ~22ms/batch ≠ 21.33ms realtime
+→ pureComp bị "stall 1.9s" giả. Với pacing chuẩn, stall đó biến mất — là
+artifact probe, KHÔNG phải VST stall.
+
+| Config | mean ms | σ | p50 | p99 | max | recv/sent |
+|---|---|---|---|---|---|---|
+| empty | 21.54 | 1.74 | 21.64 | 22.03 | 25.73 | 9996/10000 |
+| pureComp | 21.69 | 0.26 | 21.66 | 22.02 | 28.94 | 9996/10000 |
+| Ozone 11 | 21.68 | 0.15 | 21.65 | 22.02 | 23.20 | 9996/10000 |
+
+- Round-trip ≈ 21.5–21.7ms = đúng 1 batch 4 block (21.33ms) + overhead nhỏ
+  (SHM copy + bridge proc 0.001–0.45ms). Latency plugin KHÔNG nằm trong
+  round-trip — plugin latency bù bằng PDC (không chặn pipeline).
+- σ round-trip: 0.15–0.26ms (pureComp/Ozone) — RẤT nhỏ → **Gate G2 MỞ**: PDC
+  mẫu có ý nghĩa, không cần giảm jitter trước (không cần relay WS→SHM sớm).
+- empty σ=1.74: 1 outlier khởi động (min=0.04ms), p50/p99 vẫn 21.6/22.0.
+- recv=9996 < 10000: 4 block cuối chưa drain hết lúc probe kết thúc (bridge
+  chậm hơn pace probe — xem §4), không phải mất block.
+
+## 3. Inter-arrival deviation
+
+| Config | σ ms | min | max |
+|---|---|---|---|
+| empty | 9.44 | −5.33 | 38.4 |
+| pureComp | 9.36 | −5.33 | 23.5 |
+| Ozone 11 | 9.36 | −5.33 | 17.8 |
+
+Block về theo batch 4 (bridge xử lí take=4/lần) → inter-arrival lệch so với
+5.33ms lý tưởng là đặc tính batching, không phải jitter ngẫu nhiên. Round-trip
+σ (§2) là thước đo đúng cho PDC; inter-arrival dùng cho sizing FILL — xem §5.
+
+## 4. Bridge FxRTPerf
+
+| Nguồn | procAvg | procMax | loopAvg | loopMax | rate blk/s | vs realtime 187.5 |
+|---|---|---|---|---|---|---|
+| probe empty | 0.001ms | 0.05ms | 22.0ms | 1010ms | 181.7 | −3.1% |
+| probe pureComp | 0.45ms | 0.80ms | 22.0ms | 1012ms | 181.6 | −3.1% |
+| probe Ozone | 0.14ms | 0.35ms | 22.0ms | 1008ms | 181.7 | −3.1% |
+| app thật (master chain đầy) | 3.4ms | 10.0ms | 21.4ms | 156ms | 186.5 | −0.5% |
+
+- **loopMax ≈ 1s ở MỌI config probe kể cả empty** — spike 1s/lần chạy ~53s,
+  không phải VST (empty cũng có). Không xuất hiện trong log app thật gần nhất
+  (loopMax 156ms) — nghi Windows scheduler/antivirus/power, cần theo dõi khi
+  chạy thật. Probe round-trip max vẫn ≤29ms → spike xảy ra lúc bridge idle,
+  không chặn block đang xử lí.
+- **Drift: bridge chậm 0.5–3.1% so realtime** (rate < 187.5). App thật −0.5%
+  (186.5): mỗi giây thiếu ~1 block → FILL 8 block (42.7ms) cạn sau ~8s nếu
+  không có cơ chế bù. Probe −3.1% là đo có pace probe riêng (nhịp probe + nhịp
+  bridge lệch nhau); con số tin cậy cho drift thật là từ app: −0.5%.
+
+## 5. ~0.22s gồm gì (xác nhận)
+
+Latency path thực đo + hằng số app:
+
+| Thành phần | ms | Nguồn |
+|---|---|---|
+| Batching 4 block (pipeline) | ~21.6 | probe round-trip (§2) |
+| FILL buffer worklet 8 block | 42.7 | `sf-fx-realtime.js` FILL=8 |
+| Plugin latency (pureComp) | 43.9 | `getLatencySamples=2108` @48k |
+| WS/main-thread jitter (warm, p50) | ~101 | dbg.log `fx_play_first` sincePlay 38–160ms |
+| **Tổng nghe thấy (warm)** | **~210ms ≈ 0.21s** | khớp ~0.22s quan sát |
+
+- PDC hiện tại `FX_RT_ROUNDTRIP_SAMPLES=3840` (80ms) = batching ~7 block +
+  FILL 8 block — khớp thực đo (21.6 + 42.7 ≈ 64ms + WS jitter margin). Giữ
+  nguyên; `latencyTotal` (plugin thật qua `{cmd:'latency'}`) cộng thêm đúng
+  (pureComp +43.9ms).
+- Cold start VST load: 8–17s (dbg.log sincePlay 8111–17211ms), warm sau đó
+  38–160ms — là plugin init, không phải latency pipeline; không nằm trong PDC.
+- fx_stats app thật (session master): u=3 h=3 f=13 s=13 cap=1 fi=13 q=5–11 —
+  underrun hiếm, queue duy trì 5–11 block → FILL đủ hấp thụ jitter thường.
+
+## 6. Kết luận cho G2+
+
+1. **Gate G2: MỞ.** σ round-trip 0.15–0.26ms → PDC mẫu có nghĩa; không cần
+   relay WS→SHM trước G2.
+2. **Drift bridge −0.5% là phát hiện mới** (không có trong plan §1–§8): FILL
+   cạn dần trên session dài → cần quyết định: (a) chấp nhận (underrun hiếm, có
+   resume), (b) bù/resync định kỳ, (c) thêm giám sát rate. **Báo user để review
+   trước khi đưa vào plan.**
+3. **loopMax ~1s spike** (probe, cả empty): theo dõi, chưa thấy ở app thật.
+4. Plugin latency bảng §1 đủ cho G2: `graph.getLatencySamples()` sẽ thay hằng
+   số; dữ liệu hiện tại xác nhận pureComp là plugin duy nhất có latency thật.
@@ -0,0 +1,156 @@
+"""G0 probe — đo latency từng plugin + jitter round-trip ≥10k block.
+
+Dùng ĐÚNG pipeline thật (FxRealtimeSession → SHM → fx_vst_bridge → SHM),
+không sửa app code. WS browser → Python không đo được từ host; phần đó lấy
+bằng chứng từ dbg.log (fx_play_first calib + fx_stats u/s) — probe này đo
+Python pump (batching) + SHM + bridge + return.
+
+Chạy:  python native_bridge/debug/g0_latency_probe.py [--blocks 10000]
+"""
+import argparse
+import atexit
+import ctypes
+import os
+import statistics
+import sys
+import time
+
+sys.path.insert(0, os.path.abspath(os.path.join(os.path.dirname(__file__), "..", "..")))
+
+# Windows Sleep granularity mặc định 15.6ms → probe pacing ~22ms/batch ≠
+# realtime 21.33ms → số liệu round-trip lệch. Bridge C++ đã gọi
+# timeBeginPeriod(1) (RealtimeFxLoop.cpp:160); probe phải làm tương tự để
+# pacing đúng realtime.
+try:
+    _winmm = ctypes.windll.winmm
+    _winmm.timeBeginPeriod(1)
+    atexit.register(_winmm.timeEndPeriod, 1)
+except Exception:
+    pass
+
+import numpy as np  # noqa: E402
+
+from app.core.fx_realtime import FxRealtimeSession, FXRT_BLOCK  # noqa: E402
+
+SR = 48000
+PERIOD = FXRT_BLOCK / SR  # 5.333ms/block; batch 4 = 21.333ms
+
+PURECOMP = r"C:\Program Files\Common Files\VST3\Sonible\purecomp.vst3"
+OZONE = r"C:\Program Files\Common Files\VST3\iZotope\Ozone 11.vst3"
+
+CONFIGS = [
+    ("empty (passthrough)", []),
+    ("pureComp", [{"type": "vst3", "path": PURECOMP, "bypass": False, "preset_b64": ""}]),
+    ("Ozone 11", [{"type": "vst3", "path": OZONE, "bypass": False, "preset_b64": ""}]),
+]
+
+
+def make_block():
+    t = np.arange(FXRT_BLOCK, dtype=np.float32) / SR
+    s = (np.sin(2 * np.pi * 440 * t) * 0.1).astype(np.float32)
+    inter = np.empty(FXRT_BLOCK * 2, dtype=np.float32)
+    inter[0::2] = s
+    inter[1::2] = s
+    return inter.tobytes()
+
+
+def run(name, chain, n_blocks):
+    log_path = os.path.join(os.environ.get("TEMP", "."), "g0_probe_%d.log" % os.getpid())
+    os.environ["FXRT_BRIDGE_LOG"] = log_path
+    sess = FxRealtimeSession(chain, SR)
+    stats = {}
+    try:
+        sess.wait_ready(30)
+        time.sleep(1.0)  # chain ready + latency report
+        stats["plugin_latency"] = dict(sess.get_latencies())
+        blk = make_block()
+        send_t = []   # block idx -> send time (call time)
+        recv_t = []   # (block idx, recv time) — FIFO: out block j <=> in block j
+        next_idx = 0
+        batch_dur = PERIOD * 4
+        batches = n_blocks // 4
+        for b in range(batches):
+            t0 = time.perf_counter()
+            for _ in range(4):
+                send_t.append(time.perf_counter())
+                sess.write_input(blk)
+                next_idx += 1
+            sess.flush_input_stale(0.001)
+            outs = sess.read_output()
+            base = len(recv_t)
+            for k in range(len(outs)):
+                recv_t.append((base + k, time.perf_counter()))
+            dt = time.perf_counter() - t0
+            if dt < batch_dur:
+                time.sleep(batch_dur - dt)
+        # round-trip per block
+        rt = []
+        for j, tr in recv_t:
+            if j < len(send_t):
+                rt.append((tr - send_t[j]) * 1000.0)
+        # inter-arrival deviation vs ideal period
+        recv_abs = [tr for _, tr in recv_t]
+        ia = []
+        for k in range(1, len(recv_abs)):
+            ia.append((recv_abs[k] - recv_abs[k - 1]) * 1000.0 - PERIOD * 1000.0)
+        stats["roundtrip_ms"] = {
+            "n": len(rt), "mean": statistics.mean(rt), "sd": statistics.pstdev(rt),
+            "min": min(rt), "max": max(rt),
+            "p50": sorted(rt)[len(rt) // 2],
+            "p99": sorted(rt)[int(len(rt) * 0.99) - 1],
+        }
+        stats["interarrival_dev_ms"] = {
+            "n": len(ia), "mean": statistics.mean(ia), "sd": statistics.pstdev(ia),
+            "min": min(ia), "max": max(ia),
+        }
+        stats["sent"] = len(send_t)
+        stats["recv"] = len(recv_t)
+        # bridge FxRTPerf
+        perf = []
+        if os.path.exists(log_path):
+            with open(log_path, "rb") as f:
+                data = f.read().decode("utf-8", "replace")
+            for line in data.splitlines():
+                if "[FxRTPerf]" in line:
+                    perf.append(line)
+        if perf:
+            stats["bridge_perf_last"] = perf[-1].split("] ", 1)[-1]
+    finally:
+        sess.close()
+        try:
+            os.remove(log_path)
+        except OSError:
+            pass
+    return stats
+
+
+def main():
+    ap = argparse.ArgumentParser()
+    ap.add_argument("--blocks", type=int, default=10000)
+    args = ap.parse_args()
+    print("G0 probe — SR=%d block=%d n_blocks=%d (%.1fs/config)" % (SR, FXRT_BLOCK, args.blocks, args.blocks * PERIOD))
+    results = {}
+    for name, chain in CONFIGS:
+        print("\n=== %s ===" % name, flush=True)
+        st = run(name, chain, args.blocks)
+        results[name] = st
+        print("plugin_latency:", st.get("plugin_latency"))
+        rt = st.get("roundtrip_ms", {})
+        print("roundtrip_ms n=%d mean=%.3f sd=%.3f min=%.3f p50=%.3f p99=%.3f max=%.3f" %
+              (rt.get("n", 0), rt.get("mean", 0), rt.get("sd", 0), rt.get("min", 0),
+               rt.get("p50", 0), rt.get("p99", 0), rt.get("max", 0)))
+        ia = st.get("interarrival_dev_ms", {})
+        print("interarrival_dev_ms n=%d mean=%.3f sd=%.3f min=%.3f max=%.3f" %
+              (ia.get("n", 0), ia.get("mean", 0), ia.get("sd", 0), ia.get("min", 0), ia.get("max", 0)))
+        print("bridge:", st.get("bridge_perf_last", "n/a"))
+    print("\n=== JSON ===")
+    print(json_dump(results))
+
+
+def json_dump(results):
+    import json
+    return json.dumps(results, indent=1)
+
+
+if __name__ == "__main__":
+    main()