Bluetooth mic startup: honest Listening indicator, startup-time investigation
The bar turned green after 2 s on a timer even when the microphone delivered nothing. It now turns green only on real audio: RMS above 0.0005, or three consecutive chunks that are not digital silence (the virtual mic emits one stray nonzero chunk right after start, and a Bluetooth headset's floor ramps in from a few LSB). Measured 1.2-1.4 s after the key, within 0.14 s of the first real samples. diagnostics/bluetooth/ records how startup went from ~1.6 s (or never) to ~1.1-1.4 s: a btusb driver bug, two PipeWire bluez5 bugs, a 500 ms WirePlumber switch timeout and an over-broad auto-connect rule. Those fixes are machine level and live outside this repo; the patches, tools and measurements are here. STARTUP-TIME.md is the summary and explains the ~0.9 s hardware floor. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01Xoc9DJCViR7dg9eKzzAcfQ
This commit is contained in:
File diff suppressed because it is too large
Load Diff
Executable
+38
@@ -0,0 +1,38 @@
|
||||
#!/bin/bash
|
||||
# Install (or with "off": remove) the tracefs kprobes and dynamic-debug prints used to trace
|
||||
# Bluetooth SCO setup through the kernel and btusb. Needs passwordless sudo.
|
||||
S=/sys/kernel/tracing
|
||||
if [ "${1:-}" = off ]; then
|
||||
sudo -n sh -c "echo 0 > $S/events/bt/enable; echo > $S/kprobe_events; echo > $S/trace
|
||||
echo 'module btusb -p' > /sys/kernel/debug/dynamic_debug/control
|
||||
echo 'func hci_sync_conn_complete_evt -p' > /sys/kernel/debug/dynamic_debug/control"
|
||||
exit
|
||||
fi
|
||||
sudo -n sh -c "
|
||||
echo 0 > $S/events/bt/enable 2>/dev/null
|
||||
echo > $S/kprobe_events
|
||||
echo 'p:bt/notify btusb_notify evt=\$arg2:u32' >> $S/kprobe_events
|
||||
echo 'p:bt/work btusb_work' >> $S/kprobe_events
|
||||
echo 'p:bt/switch_alt btusb_switch_alt_setting new_alts=\$arg2:s32' >> $S/kprobe_events
|
||||
echo 'r:bt/switch_alt_ret btusb_switch_alt_setting ret=\$retval:s32' >> $S/kprobe_events
|
||||
echo 'p:bt/set_intf usb_set_interface ifnum=\$arg2:s32 alt=\$arg3:s32' >> $S/kprobe_events
|
||||
echo 'r:bt/set_intf_ret usb_set_interface ret=\$retval:s32' >> $S/kprobe_events
|
||||
echo 'r:bt/submit_isoc_ret btusb_submit_isoc_urb ret=\$retval:s32' >> $S/kprobe_events
|
||||
echo 'r:bt/autopm_ret usb_autopm_get_interface ret=\$retval:s32' >> $S/kprobe_events
|
||||
echo 'p:bt/conn_add hci_conn_add_unset type=\$arg2:s32' >> $S/kprobe_events
|
||||
echo 'p:bt/conn_del hci_conn_del' >> $S/kprobe_events
|
||||
echo 'p:bt/conn_failed hci_conn_failed status=\$arg2:u8' >> $S/kprobe_events
|
||||
echo 'p:bt/conn_complete hci_conn_complete_evt status=+0(\$arg2):u8 link_type=+9(\$arg2):u8' >> $S/kprobe_events
|
||||
echo 'p:bt/disconn_complete hci_disconn_complete_evt status=+0(\$arg2):u8 handle=+1(\$arg2):u16 reason=+3(\$arg2):u8' >> $S/kprobe_events
|
||||
echo 'p:bt/mode_change hci_mode_change_evt status=+0(\$arg2):u8' >> $S/kprobe_events
|
||||
echo 'p:bt/sco_setup hci_sco_setup status=\$arg2:u8' >> $S/kprobe_events
|
||||
echo 'p:bt/cs_enh_setup_sync hci_cs_enhanced_setup_sync_conn status=\$arg2:u8' >> $S/kprobe_events
|
||||
echo 'p:bt/sync_complete hci_sync_conn_complete_evt' >> $S/kprobe_events
|
||||
echo 'p:bt/connect_cfm sco_connect_cfm status=\$arg2:u8' >> $S/kprobe_events
|
||||
echo 'p:bt/sco_tx hci_send_sco' >> $S/kprobe_events
|
||||
echo 'p:bt/sco_rx_urb btusb_isoc_complete' >> $S/kprobe_events
|
||||
echo 1 > $S/events/bt/enable
|
||||
echo 'module btusb +pf' > /sys/kernel/debug/dynamic_debug/control
|
||||
echo 'func hci_sync_conn_complete_evt +pf' > /sys/kernel/debug/dynamic_debug/control
|
||||
echo > $S/trace
|
||||
echo 1 > $S/tracing_on"
|
||||
Executable
+12
@@ -0,0 +1,12 @@
|
||||
#!/bin/bash
|
||||
# Restart WirePlumber, run a traced trial, stop when the kernel logs submission failed (90).
|
||||
SC=$(dirname "$0")
|
||||
for i in 1 2 3 4 5 6; do
|
||||
systemctl --user restart wireplumber; sleep 9
|
||||
/home/tank/repos/speech-to-text/bin/stt status --json | grep -q '"state": *"idle"' || { echo "stt busy"; break; }
|
||||
T0=$(date +%s)
|
||||
"$SC/trial.sh" "repro-$i" > "$SC/repro-$i.log" 2>&1
|
||||
if sudo -n journalctl -k --since "@$T0" --no-pager | grep -q 'submission failed (90)'; then echo "REPRODUCED on attempt $i"; exit 0; fi
|
||||
echo "attempt $i: no failure"; sleep 3
|
||||
done
|
||||
echo "not reproduced"
|
||||
Executable
+22
@@ -0,0 +1,22 @@
|
||||
#!/bin/bash
|
||||
# One dictation startup trial: kernel probes + btmon + userspace timing. $1 = label
|
||||
set -u
|
||||
SC=$(dirname "$0"); L=${1:-trial}; S=/sys/kernel/tracing
|
||||
sudo -n sh -c "echo > $S/trace"
|
||||
sudo -n btmon -w "$SC/$L.btsnoop" >/dev/null 2>&1 &
|
||||
BTMON=$!
|
||||
sleep 0.5
|
||||
T0=$(date +%s.%N)
|
||||
echo "T0 unix $T0 monotonic $(python3 -c 'import time;print(round(time.monotonic(),3))')"
|
||||
python3 /tmp/stt-startup-trace.py 2>&1 | grep -vE '"graph"|audio-progress'
|
||||
sleep 0.5
|
||||
sudo -n kill $BTMON; wait $BTMON 2>/dev/null
|
||||
echo "--- ftrace"
|
||||
sudo -n cat $S/trace | grep -v '^#' | grep -vE 'sco_tx|sco_rx_urb' | sed -E 's/^ +//; s/ \[[0-9]+\] [^ ]+ / /; s/\([^)]*\)//' | cut -c1-120
|
||||
echo "--- sco tx/rx-urb per second"
|
||||
sudo -n cat $S/trace | grep -E 'sco_tx|sco_rx_urb' | sed -E 's/.* ([0-9]+)\.[0-9]+: (sco_tx|sco_rx_urb).*/\1 \2/' | sort | uniq -c | tr '\n' ';'; echo
|
||||
echo "--- dmesg"
|
||||
sudo -n journalctl -k -o short-precise --since "@${T0%.*}" --no-pager | grep -E 'Bluetooth:|hci_sync_conn|hci_conn_request|btusb_notify|__set_isoc|btusb_submit_isoc|__fill_isoc' | cut -c1-160
|
||||
echo "--- btmon (commands/events only)"
|
||||
sudo -n chown $USER "$SC/$L.btsnoop"
|
||||
btmon -r "$SC/$L.btsnoop" -t 2>/dev/null | grep -E '^[<>] HCI (Command|Event)|^\s+(Status|Handle|Link type|Air mode|Reason|Opcode|Voice setting|Transmit coding|Receive coding|RX packet length|TX packet length|Mode|Interval|Packet type|Retransmission|Max latency|Transmit bandwidth|Receive bandwidth):' | grep -vE 'HCI Event: Number of Completed|HCI Event: Command Complete.*(Read RSSI|Read Clock)|Vendor' | sed -E 's/\{[^}]*\}//' | cut -c1-140
|
||||
Executable
+94
@@ -0,0 +1,94 @@
|
||||
#!/usr/bin/env python3
|
||||
"""One F13-path dictation startup trial, timed against the kernel.
|
||||
|
||||
usage: trial2.py LABEL [--wp-restart SECS] (--wp-restart: restart WirePlumber, wait SECS, then start)
|
||||
Needs tools/kernel-probes.sh installed and `echo mono > /sys/kernel/tracing/trace_clock` (passwordless sudo).
|
||||
Starts dictation the way F13 does (`stt start`), polls the daemon for 6 s, cancels the take (nothing is
|
||||
pasted or kept), then prints a timeline relative to the start command.
|
||||
"""
|
||||
import json, os, re, socket, subprocess, sys, time
|
||||
|
||||
STT = os.path.join(os.path.dirname(os.path.abspath(__file__)), "..", "..", "..", "bin", "stt")
|
||||
SOCK = os.path.join(os.environ.get("XDG_RUNTIME_DIR", "/tmp"), "speech-to-text", "ctl.sock")
|
||||
TR = "/sys/kernel/tracing"
|
||||
|
||||
def sudo(cmd):
|
||||
return subprocess.run(["sudo", "-n", "sh", "-c", cmd], capture_output=True, text=True).stdout
|
||||
|
||||
def profile():
|
||||
out = subprocess.run(["pactl", "list", "cards"], capture_output=True, text=True).stdout
|
||||
card = out.split("Name: bluez_card.88_C9_E8_A7_EC_7E", 1)
|
||||
if len(card) < 2: return "no-card"
|
||||
m = re.search(r"Active Profile: (\S+)", card[1].split("Card #")[0])
|
||||
return m.group(1) if m else "?"
|
||||
|
||||
def status():
|
||||
s = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM); s.connect(SOCK); s.settimeout(2)
|
||||
buf = b""
|
||||
while b"\n" not in buf:
|
||||
buf += s.recv(65536)
|
||||
s.close()
|
||||
return json.loads(buf.split(b"\n", 1)[0])
|
||||
|
||||
label = sys.argv[1]
|
||||
if "--wp-restart" in sys.argv:
|
||||
wait = float(sys.argv[sys.argv.index("--wp-restart") + 1])
|
||||
subprocess.run(["systemctl", "--user", "restart", "wireplumber"], check=True)
|
||||
time.sleep(wait)
|
||||
assert status()["state"] == "idle", "stt busy"
|
||||
p0 = profile()
|
||||
assert p0.startswith("a2dp"), f"headset not in A2DP before start: {p0}"
|
||||
sudo(f"echo > {TR}/trace")
|
||||
t0m, t0w = time.monotonic(), time.time()
|
||||
subprocess.Popen([STT, "start"], stdout=subprocess.DEVNULL)
|
||||
first_nz = first_sig = listening = None
|
||||
levels = []; window = None
|
||||
while time.monotonic() - t0m < 6.0:
|
||||
st = status(); t = time.monotonic() - t0m
|
||||
if st["state"] == "recording" and st["levels"]:
|
||||
lv = st["levels"][-1]
|
||||
levels.append((round(t, 2), lv))
|
||||
if lv > 0 and first_nz is None: first_nz = t
|
||||
if lv >= 0.05 and first_sig is None: first_sig = t # rms >= 2e-4
|
||||
if st["listening"] and listening is None: listening = t
|
||||
if window is None and t >= 2.3: window = (round(t, 2), st["levels"])
|
||||
elif st["state"] != "recording" and st["state"] != "idle" and st["state"] != "opening":
|
||||
pass
|
||||
time.sleep(0.02)
|
||||
subprocess.run([STT, "cancel"], stdout=subprocess.DEVNULL)
|
||||
time.sleep(0.3)
|
||||
p_rec = profile()
|
||||
|
||||
# kernel timeline (trace clock must be "mono")
|
||||
ev = {}
|
||||
trace = sudo(f"cat {TR}/trace")
|
||||
rx = tx = 0
|
||||
for line in trace.splitlines():
|
||||
m = re.match(r"\s*\S+\s+\[\d+\]\s+\S+\s+([\d.]+):\s+(\S+):\s*(.*)", line)
|
||||
if not m: continue
|
||||
t = float(m.group(1)) - t0m; name = m.group(2); rest = m.group(3)
|
||||
if name == "sco_rx_urb": rx += 1; ev.setdefault("first_sco_rx_urb", t); continue
|
||||
if name == "sco_tx": tx += 1; ev.setdefault("first_sco_tx", t); continue
|
||||
if name == "conn_add" and "type=2" in rest: ev.setdefault("esco_connect", t)
|
||||
elif name == "cs_enh_setup_sync": ev.setdefault("enh_setup_cmd_status", t)
|
||||
elif name == "sync_complete": ev.setdefault("esco_up", t)
|
||||
elif name == "submit_isoc_ret" and "ret=-" in rest: ev.setdefault("isoc_submit_fail", t)
|
||||
elif name == "notify": ev.setdefault("notify", []).append((round(t, 3), rest))
|
||||
elif name == "switch_alt": ev.setdefault("switch_alt", []).append((round(t, 3), rest))
|
||||
elif name == "conn_complete": ev.setdefault("conn_complete", []).append((round(t, 3), rest))
|
||||
dmesg = sudo(f"journalctl -k --since @{int(t0w)-1} --no-pager -o short-precise | grep -E 'submission failed|Bluetooth' | cut -c1-140")
|
||||
|
||||
print(f"== {label}")
|
||||
for k in ("esco_connect", "enh_setup_cmd_status", "esco_up", "first_sco_rx_urb", "first_sco_tx", "isoc_submit_fail"):
|
||||
print(f"{k:22s} {ev[k]:.3f}" if k in ev else f"{k:22s} -")
|
||||
print(f"sco rx urbs {rx} sco tx {tx}")
|
||||
print(f"{'first nonzero level':22s} {first_nz:.3f}" if first_nz else f"{'first nonzero level':22s} -")
|
||||
print(f"{'first level>=0.05':22s} {first_sig:.3f}" if first_sig else f"{'first level>=0.05':22s} -")
|
||||
print(f"{'UI listening':22s} {listening:.3f}" if listening else f"{'UI listening':22s} -")
|
||||
print("notify:", ev.get("notify")); print("switch_alt:", ev.get("switch_alt")); print("conn_complete:", ev.get("conn_complete"))
|
||||
print("levels:", [l for l in levels if l[1] > 0][:12])
|
||||
if window: print(f"level window at {window[0]} s (oldest first, 50 ms each):", window[1])
|
||||
print("dmesg:", dmesg.strip() or "-")
|
||||
print("ERROR90" if "submission failed (90)" in dmesg else "no error 90")
|
||||
time.sleep(3.5)
|
||||
print(f"profile: before {p0}, during {p_rec}, 3.5 s after cancel {profile()}")
|
||||
Reference in New Issue
Block a user