Commit 0d184046 by PLN (Algolia)

fix(obs): half the lens was dead code, and it took a device swap to notice

Three fixes, found by pointing the tool at the laptop's built-in card when PLN
moved upstairs and played UMC-less out of the aux jack into a Pioneer amp.

1. The rate and STALL checks never ran. They compared consecutive polls and
   required dt > 0.5 s, but the default poll interval is 0.25 s, so the
   condition was almost never true: the 900 s watch that diagnosed the UMC
   collected exactly TWO rate samples. The restart detector carried the entire
   investigation while the other half of the tool was decoration. Now measured
   against a reference sample held at least a second back, which also makes
   'RUNNING but hw_ptr frozen' a check that can actually fire. Verified: 11
   samples in 12 s, 47984/47996/48034 Hz.

2. It watched pcm0p unconditionally. Fine for a USB interface with one playback
   PCM; wrong for the SOF card, which has eight (headphones, speakers, mics,
   HDMI) and where which one is live depends on where the jack is. It would
   have reported perfect health about the speakers while the sound went out the
   headphone jack. Now prefers a RUNNING substream, re-resolved every poll, and
   says so when the live PCM moves.

3. nominal_rate read stream0, which is USB-audio-only, so it returned None on
   the built-in card — disabling the rate comparison on exactly the device PLN
   falls back to when the interface dies. Falls back to hw_params.

Also stops crying wolf: a stream that just restarted has a hw_ptr counting from
zero, so the first delta across the seam is meaningless. Measuring it anyway
printed 'RATE OFF - 0 Hz (-100%)' on every reconnect during the replug test — a
false alarm fired at the exact moment the operator most needs to trust the
tool.

The lesson is the one this repo keeps relearning: a check that never fires is
indistinguishable from a check that passes, and you only find it by running the
thing somewhere new.
parent 13c12b62
...@@ -80,9 +80,47 @@ def find_card(name_match: str) -> tuple[int, str] | tuple[None, None]: ...@@ -80,9 +80,47 @@ def find_card(name_match: str) -> tuple[int, str] | tuple[None, None]:
return None, None return None, None
def read_sub(card: int, direction: str) -> dict | None: def pick_pcm(card: int, direction: str) -> str | None:
"""Name of the PCM device to watch, e.g. 'pcm0p'.
A USB interface has one playback PCM and picking it is trivial. The
laptop's built-in SOF card has EIGHT (pcm0p pcm1c pcm2p pcm31p pcm4c
pcm5p pcm6p pcm7p) — headphones, speakers, mics, HDMI — and which one
carries the sound depends on where the jack is. Hardcoding pcm0p there
would have quietly watched the speakers while PLN played out of the
headphone jack into an amp: a lens reporting perfect health about a
device nobody is listening to.
So: prefer a RUNNING substream, fall back to the lowest-numbered one that
exists. Re-resolved on every poll, because which PCM is live changes when
a jack moves.
"""
base = PROC / f"card{card}"
try:
cands = sorted(
(p for p in base.glob(f"pcm*{direction}") if p.is_dir()),
key=lambda p: int(re.sub(r"\D", "", p.name) or 0),
)
except OSError:
return None
fallback = None
for p in cands:
if fallback is None:
fallback = p.name
try:
if (p / "sub0" / "status").read_text().startswith("state: RUNNING"):
return p.name
except OSError:
continue
return fallback
def read_sub(card: int, direction: str, pcm: str | None = None) -> dict | None:
"""Parse one substream's status. direction is 'p' (playback) or 'c'.""" """Parse one substream's status. direction is 'p' (playback) or 'c'."""
p = PROC / f"card{card}" / f"pcm0{direction}" / "sub0" / "status" pcm = pcm or pick_pcm(card, direction)
if pcm is None:
return None
p = PROC / f"card{card}" / pcm / "sub0" / "status"
try: try:
txt = p.read_text() txt = p.read_text()
except OSError: except OSError:
...@@ -100,14 +138,30 @@ def read_sub(card: int, direction: str) -> dict | None: ...@@ -100,14 +138,30 @@ def read_sub(card: int, direction: str) -> dict | None:
return out return out
def nominal_rate(card: int) -> int | None: def nominal_rate(card: int, pcm: str | None = None) -> int | None:
"""Momentary frequency the hardware reports, from stream0.""" """The rate the hardware says it is running at.
stream0 is a USB-audio-only file, so on the built-in SOF card it does not
exist and the first version of this returned None — which made every rate
check silently unavailable on exactly the device PLN fell back to when the
interface died. hw_params is the portable answer.
"""
try: try:
txt = (PROC / f"card{card}" / "stream0").read_text() txt = (PROC / f"card{card}" / "stream0").read_text()
m = re.search(r"Momentary freq = (\d+) Hz", txt)
if m:
return int(m.group(1))
except OSError: except OSError:
return None pass
m = re.search(r"Momentary freq = (\d+) Hz", txt) for name in ([pcm] if pcm else []) + ["pcm0p"]:
return int(m.group(1)) if m else None try:
txt = (PROC / f"card{card}" / name / "sub0" / "hw_params").read_text()
except OSError:
continue
m = re.search(r"^rate:\s*(\d+)", txt, re.M)
if m:
return int(m.group(1))
return None
def kernel_counts() -> dict[str, int]: def kernel_counts() -> dict[str, int]:
...@@ -133,6 +187,8 @@ class Watcher: ...@@ -133,6 +187,8 @@ class Watcher:
self.device = device self.device = device
self.verbose = verbose self.verbose = verbose
self.prev: dict[str, dict] = {} self.prev: dict[str, dict] = {}
self.pcms: dict[str, str] = {}
self.ref: dict[str, dict] = {} # rate reference, kept >=1s back
self.card: int | None = None self.card: int | None = None
self.events: list[str] = [] self.events: list[str] = []
self.restarts = {"playback": 0, "capture": 0} self.restarts = {"playback": 0, "capture": 0}
...@@ -155,6 +211,8 @@ class Watcher: ...@@ -155,6 +211,8 @@ class Watcher:
self.gone_since = time.time() self.gone_since = time.time()
self.card = None self.card = None
self.prev.clear() self.prev.clear()
self.pcms.clear()
self.ref.clear()
return return
if self.card != card: if self.card != card:
if self.gone_since is not None: if self.gone_since is not None:
...@@ -169,7 +227,15 @@ class Watcher: ...@@ -169,7 +227,15 @@ class Watcher:
self.card = card self.card = card
for direction, key in (("p", "playback"), ("c", "capture")): for direction, key in (("p", "playback"), ("c", "capture")):
cur = read_sub(card, direction) pcm = pick_pcm(card, direction)
# Which PCM is live is itself an event: on a multi-PCM card it moves
# when a jack moves, and it must be said out loud or the numbers
# below describe a device the reader is not thinking about.
if pcm and self.pcms.get(key) != pcm:
if self.pcms.get(key):
self.log(f"{key:<8} now on {pcm} (was {self.pcms[key]})")
self.pcms[key] = pcm
cur = read_sub(card, direction, pcm)
if cur is None: if cur is None:
continue continue
old = self.prev.get(key) old = self.prev.get(key)
...@@ -179,8 +245,17 @@ class Watcher: ...@@ -179,8 +245,17 @@ class Watcher:
self.log(f"{key:<8} {cur['state']}", keep=False) self.log(f"{key:<8} {cur['state']}", keep=False)
continue continue
# A stream that just (re)started has a hw_ptr counting from zero, so
# the first delta across the seam is meaningless. Measuring it anyway
# printed "RATE OFF - 0 Hz effective (-100%)" on every reconnect
# during the 2026-08-14 replug test: a false alarm, fired at exactly
# the moment the operator most needs to trust the tool. A lens that
# cries wolf at every gig start is worse than no lens.
fresh = False
if cur["state"] != old["state"]: if cur["state"] != old["state"]:
self.log(f"{key:<8} state {old['state']} -> {cur['state']}") self.log(f"{key:<8} state {old['state']} -> {cur['state']}")
fresh = True
# The restart detector. trigger_time moving means the stream was # The restart detector. trigger_time moving means the stream was
# stopped and started again — silence, and a truncated head on # stopped and started again — silence, and a truncated head on
...@@ -191,15 +266,30 @@ class Watcher: ...@@ -191,15 +266,30 @@ class Watcher:
self.restarts[key] += 1 self.restarts[key] += 1
self.log(f"{key:<8} !! STREAM RESTARTED " self.log(f"{key:<8} !! STREAM RESTARTED "
f"(previous stream lived {lived:.1f}s)") f"(previous stream lived {lived:.1f}s)")
fresh = True
# Effective rate: the arithmetic that separates "set up" from # Effective rate: the arithmetic that separates "set up" from
# "moving", and a clock mismatch from a healthy device. # "moving", and a clock mismatch from a healthy device.
dh = cur.get("hw_ptr", 0) - old.get("hw_ptr", 0) #
dt = cur.get("tstamp", 0) - old.get("tstamp", 0) # Measured against a REFERENCE sample kept at least a second back,
if dt > 0.5 and dh >= 0 and cur["state"] == "RUNNING": # not against the previous poll. The first version compared
# consecutive polls and required dt > 0.5 s — but the default poll
# interval is 0.25 s, so that condition was almost never true and
# the rate and STALL checks silently never ran. A 900 s watch
# collected two rate samples. The restart detector carried the whole
# investigation while half the tool was dead code, which is the
# failure mode where a green check proves nothing at all.
ref = self.ref.get(key)
if fresh or ref is None:
self.ref[key] = cur
ref = None
dh = cur.get("hw_ptr", 0) - (ref or {}).get("hw_ptr", 0)
dt = cur.get("tstamp", 0) - (ref or {}).get("tstamp", 0)
if ref is not None and dt >= 1.0 and dh >= 0 and cur["state"] == "RUNNING":
self.ref[key] = cur
eff = dh / dt eff = dh / dt
self.rates[key].append(eff) self.rates[key].append(eff)
nom = nominal_rate(card) or 48000 nom = nominal_rate(card, self.pcms.get(key)) or 48000
if dh == 0: if dh == 0:
self.log(f"{key:<8} !! STALLED — RUNNING but hw_ptr frozen " self.log(f"{key:<8} !! STALLED — RUNNING but hw_ptr frozen "
f"for {dt:.1f}s") f"for {dt:.1f}s")
...@@ -260,13 +350,13 @@ def main(): ...@@ -260,13 +350,13 @@ def main():
return 1 return 1
if a.once: if a.once:
print(f"card{card} — {desc} nominal {nominal_rate(card)} Hz") print(f"card{card} — {desc} nominal {nominal_rate(card, pick_pcm(card, 'p'))} Hz")
for direction, key in (("p", "playback"), ("c", "capture")): for direction, key in (("p", "playback"), ("c", "capture")):
s = read_sub(card, direction) or {} pcm = pick_pcm(card, direction)
s = read_sub(card, direction, pcm) or {}
age = (s.get("tstamp", 0) - s.get("trigger_time", 0)) if s.get("trigger_time") else None age = (s.get("tstamp", 0) - s.get("trigger_time", 0)) if s.get("trigger_time") else None
print(f" {key:<9} state={s.get('state','?'):<9} " head = f" {key:<9} {str(pcm or '-'):<7} state={s.get('state','?'):<9}"
f"stream age {age:.1f}s" if age is not None print(f"{head} stream age {age:.1f}s" if age is not None else head)
else f" {key:<9} state={s.get('state','?')}")
print("\nA snapshot cannot see a restart — that needs two reads. " print("\nA snapshot cannot see a restart — that needs two reads. "
"Use --watch N.") "Use --watch N.")
return 0 return 0
...@@ -274,7 +364,7 @@ def main(): ...@@ -274,7 +364,7 @@ def main():
w = Watcher(a.device, a.verbose) w = Watcher(a.device, a.verbose)
kern_before = kernel_counts() kern_before = kernel_counts()
print(f"audio-lens on card{card} — {desc}") print(f"audio-lens on card{card} — {desc}")
print(f"nominal {nominal_rate(card)} Hz · polling {a.interval}s · " print(f"nominal {nominal_rate(card, pick_pcm(card, 'p'))} Hz · polling {a.interval}s · "
f"{'watching ' + str(int(a.watch)) + 's' if a.watch else 'Ctrl-C to stop'}") f"{'watching ' + str(int(a.watch)) + 's' if a.watch else 'Ctrl-C to stop'}")
print("passive: opens no PCM, plays nothing\n") print("passive: opens no PCM, plays nothing\n")
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment