Android: make the app say what it is doing, then count what the audio path misses #191
Merged
logan
merged 2 commits from 2026-08-21 20:47:45 +00:00
135-android-underrun-instrumentation into main
2
Commits
| Author | SHA1 | Message | Date | |
|---|---|---|---|---|
 logan
|
842fe47e9e |
feat(player): count what the ring buffer misses
An underrun is audible and nothing counted it. When the ring is empty BufferedStreamer.Stream zeroes the caller's buffer and returns ok, so a run of zeros is spliced into the waveform and the step discontinuity at each edge is a click; a series of short ones is static. That is the one candidate in #135 whose audible signature matches the report. `starved` and `starvedSince` already existed, from #122's stall fix, and could not answer this: they are a *stall* detector, reset by every arriving sample, because their job is to end a track whose source has died and a merely slow source must not be cut short. That reset is exactly what made the audible case invisible -- a hundred 20ms underruns a minute never approach the give-up threshold, so they were invisible to the log, to the UI and to every tier. UnderrunStats counts runs, calls and samples for the life of the streamer. Runs is the number that means something audible: one episode is one pop however many callbacks it spans, and the ratio of runs to calls is what separates clicking from dropping out. Three things about the reporting are deliberate. **Counting is in Stream and reporting is not.** Stream runs on the speaker callback's real-time deadline, so a log line there would allocate, format and write on the exact path whose missed deadline is the defect -- measuring by making it worse. The count is two increments under a lock that was already held; the report is on the 1 Hz position ticker, which only runs while playing. **An unchanged count is not logged**, which is emitStatus' rule one package over. A healthy player is silent, so anything in the log is news and the line appears exactly while it is popping. **It is Info rather than Debug.** The default level is Info and a phone has no convenient way to set YJ_LOG_LEVEL, so a debug line here would be a counter nobody on the affected platform could read -- which is the shape of the bug that made #160 necessary. underrunDelta clamps at zero because the counter belongs to the streamer and the streamer is replaced on every track: a baseline carried across that boundary is the previous track's total subtracted from a fresh zero. The baseline is reset at the load as well; a negative count in a log line reads as a broken instrument and would discredit the measurement this exists to make. This is the instrument, not a fix. What it measures is on the issue. |
||
|
logan
|
168e588387 |
feat(android): route slog to logcat
Every slog line the app wrote on Android went to /dev/null, including the one naming the error it was about to os.Exit on. #52 is what that cost: a process that vanished with no tombstone, no AndroidRuntime stack and nothing in `logcat -b crash`, at Priority/Critical for months, whose entire diagnosis was one sLogger.Error main.go was already writing. backend/androidlog is a slog.Handler over __android_log_write, chosen in main() by build tag rather than by a runtime check so that a desktop binary links no cgo for a platform it cannot run on. **Everything except the write itself is untagged.** That is androidpayload.go's discipline pushed as far as it goes: the only toolchain that compiles the android tag is a cross-compiler and the only thing that runs it is a phone, so the priority mapping, the formatting, the chunking and the handler's own attr and group bookkeeping are ordinary Go that `go test` exercises everywhere, and android.go is fifteen lines that hand a string to liblog. Four things in it are load-bearing. **The tag is a fixed string, not the application id.** The debug build carries `applicationIdSuffix ".dev"` so it can be installed beside the release app, and it is the only build whose WebView can be inspected -- so a tag derived from the id is a different tag on the one build anybody debugging this app is running, and the filter meant to show these lines would hide them exactly where they were being looked for. **The priorities are android/log.h's own values, asserted twice.** android.go carries constant expressions that do not compile as uint if the header renumbers; the untagged test writes the six numbers out longhand, because comparing a constant to itself passes on any renumbering. A wrong priority is the failure that hides rather than breaks -- logcat prints whatever number it is handed, so an Error filed as Info is present, correct, and invisible to every filter. **Formatting is delegated to slog's TextHandler.** WithAttrs and WithGroup are the half of slog.Handler that is easy to get subtly wrong, and a logger whose groups are wrong is a logger nobody reads. The derived handlers share the parent's buffer *and its mutex*: a second mutex would guard nothing, and two loggers derived from one would splice their bytes into a single line under load. **A line is chunked, because liblog drops what does not fit.** The kernel logger's entry is 4068 bytes for tag and message together and the remainder goes without comment, so a long record would be truncated in the middle of the thing worth reading. Time and level are dropped from the formatted line, since logcat stamps every entry with both -- and dropping them by *key* also ate a caller's own "level" attribute, which the on-device probe caught and TestACallersOwnLevelAttrSurvives now holds. ReplaceAttr sees an empty group path for the built-ins and for every top-level attribute alike, so the kinds are what separate them. Verified on the reference device (TLP301, Android 14): a debug build logs I/W/E under the `yellowjacket` tag at the right priorities, and the first thing it surfaced was a real warning nobody could previously see -- `champion index rebuild failed ... disk I/O error (6410)`. Closes #160 |