diff --git a/JUCE_LATENCY_PLAN.md b/JUCE_LATENCY_PLAN.md index 3cf52f8..8beefe6 100644 --- a/JUCE_LATENCY_PLAN.md +++ b/JUCE_LATENCY_PLAN.md @@ -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) diff --git a/native_bridge/debug/G0_RESULTS.md b/native_bridge/debug/G0_RESULTS.md new file mode 100644 index 0000000..3394424 --- /dev/null +++ b/native_bridge/debug/G0_RESULTS.md @@ -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. diff --git a/native_bridge/debug/g0_latency_probe.py b/native_bridge/debug/g0_latency_probe.py new file mode 100644 index 0000000..38fdab6 --- /dev/null +++ b/native_bridge/debug/g0_latency_probe.py @@ -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()