Files
FilmForge/GUI/_diag_latency.py
T
hulk 8035f9b7d3 GUI v0.2.9: fix chronic-lag root cause (log trim crash on PySide6 6.11) + 5 hardening fixes
- log trim used instance-level enum access (removed in PySide6 6.11), crashed
2026-10-12 16:14:53 +08:00

233 lines
8.3 KiB
Python

#!/usr/bin/env python3
# -*- coding: utf-8 -*-
"""诊断 v2: 干净基线 — 旁路 app_fluent._log 的坏裁剪(cursor.Start 在 PySide6
6.11.2 上抛 AttributeError), 用 Qt 原生 setMaximumBlockCount 替代, 其余不动源码。
目的: 验证 100ms 持续上报数分钟下, 修复裁剪后 点击->TX 是否仍瞬时、事件循环
是否仍流畅(对照 buggy 版的 tick 中止 + 队列积压)。"""
import ctypes
import gc
import os
import sys
import threading
import time
os.environ.setdefault("QT_QPA_PLATFORM", "offscreen")
sys.path.insert(0, os.path.dirname(os.path.abspath(__file__)))
import filmforge_rs485 as ff
class FakeSerial:
"""模拟 CH34x + 固件: M2S<ms> 控制周期温度帧, M2S0 回 ok 并停流。"""
def __init__(self, *a, **kw):
self._buf = bytearray()
self._lock = threading.Lock()
self._alive = True
self.write_log = [] # [(time, cmd_bytes)]
self.report_ms = 0
self._next_tx = 0.0
self._th = threading.Thread(target=self._fw, daemon=True)
self._th.start()
FakeSerial.last = self
def _fw(self):
while self._alive:
now = time.time()
if self.report_ms and now >= self._next_tx:
self._push(self._frame("34.6"))
self._next_tx = now + self.report_ms / 1000.0
time.sleep(0.002)
@staticmethod
def _frame(payload, type_code=0xF0):
body = bytes([type_code, len(payload)]) + payload.encode("ascii")
return bytes([0xB5]) + body + bytes([ff.sum_crc(body)])
def _push(self, b):
with self._lock:
self._buf += b
@property
def in_waiting(self):
with self._lock:
return len(self._buf)
def read(self, n):
deadline = time.time() + 0.15
while True:
with self._lock:
if self._buf:
out = bytes(self._buf[:n])
del self._buf[:n]
return out
if time.time() >= deadline:
return b""
time.sleep(0.004)
def write(self, data):
self.write_log.append((time.time(), bytes(data)))
cmd = bytes(data[3:-1]).decode("ascii", "replace").strip()
threading.Timer(0.05, lambda: self._on_cmd(cmd)).start()
return len(data)
def _on_cmd(self, cmd):
if cmd.startswith("M2S"):
try:
ms = int(cmd[3:])
except ValueError:
ms = 0
self.report_ms = ms
self._next_tx = time.time() + ms / 1000.0
self._push(self._frame("ok"))
elif cmd in ("M1", "M2", "M3", "M4", "M999"):
self._push(self._frame({"M1": "34.6", "M2": "OFF", "M3": "OFF",
"M4": "35.0", "M999": "v41.0.0.1"}[cmd]))
else:
self._push(self._frame("ok"))
def close(self):
self._alive = False
try:
self._th.join(timeout=0.5)
except Exception:
pass
ff.serial.Serial = FakeSerial
from PySide6.QtCore import QTimer
from PySide6.QtWidgets import QApplication
app = QApplication([])
import app_fluent
# ---- 测试侧修复: 旁路坏裁剪(原生上限 500 行, 语义等同原意图) ----
window = app_fluent.App(0)
window.txt_log.setMaximumBlockCount(500) # blockCount 永不 >500, 坏分支不触发
window.show()
fake = None
exception_count = [0]
# ---- 指标 ----
stats = {"paint": [0, 0.0, 0.0], "tick": [0, 0.0, 0.0],
"gc": [0, 0.0, 0.0], "drift": [], "qmax": [0], "click": []}
_orig_paint = app_fluent.TemperatureChart.paintEvent
def timed_paint(self, ev):
t0 = time.perf_counter()
_orig_paint(self, ev)
dt = time.perf_counter() - t0
s = stats["paint"]; s[0] += 1; s[1] += dt; s[2] = max(s[2], dt)
app_fluent.TemperatureChart.paintEvent = timed_paint
_orig_tick = app_fluent.App._tick
def timed_tick(self):
t0 = time.perf_counter()
try:
_orig_tick(self)
except Exception as e:
exception_count[0] += 1
if exception_count[0] <= 3:
print("TICK EXCEPTION:", e, flush=True)
dt = time.perf_counter() - t0
s = stats["tick"]; s[0] += 1; s[1] += dt; s[2] = max(s[2], dt)
app_fluent.App._tick = timed_tick
_gc_t = [0.0]
def gc_cb(phase, info):
if phase == "start":
_gc_t[0] = time.perf_counter()
else:
dt = time.perf_counter() - _gc_t[0]
s = stats["gc"]; s[0] += 1; s[1] += dt; s[2] = max(s[2], dt)
gc.callbacks.append(gc_cb)
probe = {"expect": None}
def probe_fire():
now = time.time()
if probe["expect"] is None:
probe["expect"] = now + 0.02
return
stats["drift"].append((now, now - probe["expect"]))
probe["expect"] += 0.02
if now - probe["expect"] > 0.5:
probe["expect"] = now + 0.02
pt = QTimer(); pt.timeout.connect(probe_fire); pt.start(20)
CLICK_PERIOD = 30
click = {"expect": None, "n": 0}
def do_click_stop():
now = time.time()
drift_ms = (now - click["expect"]) * 1000 if click["expect"] else 0.0
q0 = window._rx_q.qsize()
window._send_set("M2S0", "report", ("OFF", None)) # "停止"按钮真实路径
click["n"] += 1
stats["click"].append(dict(n=click["n"], t=now, drift_ms=drift_ms,
qsize=q0, pending=len(window._pending),
samples=len(window.samples_t),
logblk=window.txt_log.blockCount()))
QTimer.singleShot(3000, do_click_restart)
def do_click_restart():
window._send_set("M2S100", "report", ("ON", 100))
click["expect"] = time.time() + CLICK_PERIOD
QTimer.singleShot(CLICK_PERIOD * 1000, do_click_stop)
def start():
global fake
window.link.open("COMFAKE", 115200)
def wait_conn():
if window.link.is_connected():
fake = FakeSerial.last
click["expect"] = time.time() + 15
QTimer.singleShot(15000, do_click_stop)
print("[t0] connected; stop-clicks every %ds from +15s" % CLICK_PERIOD,
flush=True)
else:
QTimer.singleShot(200, wait_conn)
QTimer.singleShot(200, wait_conn)
QTimer.singleShot(100, start)
t_start = time.time()
DURATION = float(sys.argv[1]) if len(sys.argv) > 1 else 320.0
INTERVAL = float(sys.argv[2]) if len(sys.argv) > 2 else 40.0
def monitor():
while time.time() - t_start < DURATION:
time.sleep(INTERVAL)
el = time.time() - t_start
recent = [d for t, d in stats["drift"] if t >= time.time() - INTERVAL]
rmax = max(recent) * 1000 if recent else 0
stats["qmax"][0] = max(stats["qmax"][0], window._rx_q.qsize())
print(f"[{el:6.1f}s] cpu={time.process_time():7.2f}s "
f"samples={len(window.samples_t):6d} q={window._rx_q.qsize():4d} "
f"(max {stats['qmax'][0]:4d}) logblk={window.txt_log.blockCount():4d} "
f"paint(n={stats['paint'][0]:5d} max={stats['paint'][2]*1000:6.1f}ms) "
f"tick_max={stats['tick'][2]*1000:6.1f}ms "
f"gc_max={stats['gc'][2]*1000:5.1f}ms drift_max={rmax:7.1f}ms "
f"exc={exception_count[0]}", flush=True)
print("==== CLICK 明细 ====", flush=True)
for c in stats["click"]:
tx = next((t for t, d in FakeSerial.last.write_log
if d[3:-1].decode("ascii", "replace") == "M2S0"
and c["t"] <= t <= c["t"] + 2.0), None)
total = (tx - c["t"]) * 1000 if tx else -1
print(f"click#{c['n']} t=+{c['t']-t_start:6.1f}s 调度漂移={c['drift_ms']:8.1f}ms "
f"click->TX={total:7.1f}ms q={c['qsize']:4d} pending={c['pending']} "
f"samples={c['samples']:6d} logblk={c['logblk']}", flush=True)
ds = sorted(d for _t, d in stats["drift"])
if ds:
print(f"drift: n={len(ds)} p50={ds[len(ds)//2]*1000:.1f}ms "
f"p99={ds[int(len(ds)*0.99)]*1000:.1f}ms max={ds[-1]*1000:.1f}ms "
f">500ms次数={sum(1 for d in ds if d>0.5)}", flush=True)
print(f"paint total={stats['paint'][1]:.2f}s max={stats['paint'][2]*1000:.1f}ms | "
f"tick total={stats['tick'][1]:.2f}s max={stats['tick'][2]*1000:.1f}ms | "
f"gc total={stats['gc'][1]:.2f}s max={stats['gc'][2]*1000:.1f}ms "
f"n={stats['gc'][0]} | exceptions={exception_count[0]}", flush=True)
os._exit(0)
threading.Thread(target=monitor, daemon=True).start()
app.exec()