Two commits, in the order they had to happen: the second one's whole
purpose is a number that can only be read on a device, and until the
first one landed every slog line on that device went to /dev/null.
backend/androidlog is a slog.Handler over __android_log_write,
selected in main() by build tag so a desktop binary links no cgo.
Everything except the write is untagged, which 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 attr/group bookkeeping are
ordinary Go that go test runs everywhere, and android.go is fifteen
lines that hand a string to liblog.
The tag is a fixed yellowjacket rather than the application id,
because the debug build carries applicationIdSuffix ".dev" and is the
only build whose WebView can be inspected — so an id-derived tag is a different tag on the one build anybody debugging this app is running. scripts/android-emulator.sh logs filters it.
The priorities are asserted twice: android.go carries constant
expressions that fail to compile as uint if android/log.h
renumbers, and the untagged test writes the six values 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.
starved/starvedSince existed from #122 but are a stall detector,
reset by every arriving sample. That reset is why the audible case was
invisible: a hundred 20 ms underruns a minute never approach the
give-up threshold. UnderrunStats counts runs, calls and samples
cumulatively; counting is two increments under a lock Stream already
holds, and reporting is on the 1 Hz position ticker, because a log line
on the speaker callback's real-time deadline would be a cause of the
defect rather than a measurement of it. An unchanged count is not
logged, so a healthy player is silent and anything in the log is news.
#135 is deliberately not closed. This measures; the measurement is
posted on the issue and it reorders the candidates.
Verification
Every gate, plus the device:
make lint (3 configs), make test (3 configs), make ui-test
(1007 tests), make e2e (236 specs, chromium — webkit is CI's), make css-check, make bindings-check, make skill-check, tsc --noEmit in frontend/ and e2e/. The frontend gates are
formalities here: this PR touches no TypeScript.
Cross-compiled GOOS=android GOARCH=arm64 CGO_ENABLED=1 for ./backend/... and for the real -buildmode=c-shared binary.
Both new test files were proved to bite by reverting the code
under them — eight separate reversions, each producing the failure
the test is named for.
On the reference device (TLP301, Android 14, arm64): a debug
build logs I/W/E under the yellowjacket tag at the right
priorities; the underrun report is live at 1 Hz (checked with a
temporary unconditional build) and silent while playback is healthy.
Two findings filed from the first minute of logcat
#160 paid for itself before it was committed. Both of these have been
written on every launch and were being discarded:
#189 — release-group MBID backfill queries a table renamed away in plan 013. Two raw-SQL statements still say release_groups; the
backfill has failed on its first statement on every launch since e7748f1.
#190 — Android: SQLite has no temp directory, so the champion index never builds. disk I/O error (6410) decodes to SQLITE_IOERR_GETTEMPPATH; the device has no /tmp and the app's
process has no TMPDIR.
Two commits, in the order they had to happen: the second one's whole
purpose is a number that can only be read on a device, and until the
first one landed every `slog` line on that device went to `/dev/null`.
| commit | issue |
|---|---|
| `feat(android): route slog to logcat` | #160 |
| `feat(player): count what the ring buffer misses` | #135 (instrument only — stays open) |
They are one PR rather than two because they are one measurement, and
because the runner has capacity 1: two stacked PRs is two full `check`
+ `e2e` cycles to land a change the second half cannot be verified
without the first.
## #160 — slog reaches logcat
`backend/androidlog` is a `slog.Handler` over `__android_log_write`,
selected in `main()` by build tag so a desktop binary links no cgo.
**Everything except the write is untagged**, which 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 attr/group bookkeeping are
ordinary Go that `go test` runs everywhere, and `android.go` is fifteen
lines that hand a string to liblog.
The tag is a fixed `yellowjacket` rather than the application id,
because the debug build carries `applicationIdSuffix ".dev"` and is the
only build whose WebView can be inspected — so an id-derived tag is a
*different* tag on the one build anybody debugging this app is running.
`scripts/android-emulator.sh logs` filters it.
The priorities are asserted twice: `android.go` carries constant
expressions that fail to compile as `uint` if `android/log.h`
renumbers, and the untagged test writes the six values 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.
## #135 — the instrument, not the fix
`starved`/`starvedSince` existed from #122 but are a *stall* detector,
reset by every arriving sample. That reset is why the audible case was
invisible: a hundred 20 ms underruns a minute never approach the
give-up threshold. `UnderrunStats` counts runs, calls and samples
cumulatively; counting is two increments under a lock `Stream` already
holds, and reporting is on the 1 Hz position ticker, because a log line
on the speaker callback's real-time deadline would be a cause of the
defect rather than a measurement of it. An unchanged count is not
logged, so a healthy player is silent and anything in the log is news.
**#135 is deliberately not closed.** This measures; the measurement is
posted on the issue and it reorders the candidates.
## Verification
Every gate, plus the device:
- `make lint` (3 configs), `make test` (3 configs), `make ui-test`
(1007 tests), `make e2e` (236 specs, chromium — webkit is CI's),
`make css-check`, `make bindings-check`, `make skill-check`,
`tsc --noEmit` in `frontend/` and `e2e/`. The frontend gates are
formalities here: this PR touches no TypeScript.
- Cross-compiled `GOOS=android GOARCH=arm64 CGO_ENABLED=1` for
`./backend/...` and for the real `-buildmode=c-shared` binary.
- **Both new test files were proved to bite** by reverting the code
under them — eight separate reversions, each producing the failure
the test is named for.
- **On the reference device** (TLP301, Android 14, arm64): a debug
build logs I/W/E under the `yellowjacket` tag at the right
priorities; the underrun report is live at 1 Hz (checked with a
temporary unconditional build) and silent while playback is healthy.
## Two findings filed from the first minute of logcat
#160 paid for itself before it was committed. Both of these have been
written on every launch and were being discarded:
- #189 — `release-group MBID backfill queries a table renamed away in
plan 013`. Two raw-SQL statements still say `release_groups`; the
backfill has failed on its first statement on every launch since
`e7748f1`.
- #190 — `Android: SQLite has no temp directory, so the champion index
never builds`. `disk I/O error (6410)` decodes to
`SQLITE_IOERR_GETTEMPPATH`; the device has no `/tmp` and the app's
process has no `TMPDIR`.
Closes #160
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
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.
Blocking a user prevents them from interacting with repositories, such as opening or commenting on pull requests or issues. Learn more about blocking a user.
Two commits, in the order they had to happen: the second one's whole
purpose is a number that can only be read on a device, and until the
first one landed every
slogline on that device went to/dev/null.feat(android): route slog to logcatfeat(player): count what the ring buffer missesThey are one PR rather than two because they are one measurement, and
because the runner has capacity 1: two stacked PRs is two full
checke2ecycles to land a change the second half cannot be verifiedwithout the first.
#160 — slog reaches logcat
backend/androidlogis aslog.Handlerover__android_log_write,selected in
main()by build tag so a desktop binary links no cgo.Everything except the write is untagged, which is
androidpayload.go's discipline pushed as far as it goes: the onlytoolchain that compiles the
androidtag is a cross-compiler and theonly thing that runs it is a phone, so the priority mapping, the
formatting, the chunking and the handler's attr/group bookkeeping are
ordinary Go that
go testruns everywhere, andandroid.gois fifteenlines that hand a string to liblog.
The tag is a fixed
yellowjacketrather than the application id,because the debug build carries
applicationIdSuffix ".dev"and is theonly build whose WebView can be inspected — so an id-derived tag is a
different tag on the one build anybody debugging this app is running.
scripts/android-emulator.sh logsfilters it.The priorities are asserted twice:
android.gocarries constantexpressions that fail to compile as
uintifandroid/log.hrenumbers, and the untagged test writes the six values 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.
#135 — the instrument, not the fix
starved/starvedSinceexisted from #122 but are a stall detector,reset by every arriving sample. That reset is why the audible case was
invisible: a hundred 20 ms underruns a minute never approach the
give-up threshold.
UnderrunStatscounts runs, calls and samplescumulatively; counting is two increments under a lock
Streamalreadyholds, and reporting is on the 1 Hz position ticker, because a log line
on the speaker callback's real-time deadline would be a cause of the
defect rather than a measurement of it. An unchanged count is not
logged, so a healthy player is silent and anything in the log is news.
#135 is deliberately not closed. This measures; the measurement is
posted on the issue and it reorders the candidates.
Verification
Every gate, plus the device:
make lint(3 configs),make test(3 configs),make ui-test(1007 tests),
make e2e(236 specs, chromium — webkit is CI's),make css-check,make bindings-check,make skill-check,tsc --noEmitinfrontend/ande2e/. The frontend gates areformalities here: this PR touches no TypeScript.
GOOS=android GOARCH=arm64 CGO_ENABLED=1for./backend/...and for the real-buildmode=c-sharedbinary.under them — eight separate reversions, each producing the failure
the test is named for.
build logs I/W/E under the
yellowjackettag at the rightpriorities; the underrun report is live at 1 Hz (checked with a
temporary unconditional build) and silent while playback is healthy.
Two findings filed from the first minute of logcat
#160 paid for itself before it was committed. Both of these have been
written on every launch and were being discarded:
release-group MBID backfill queries a table renamed away in plan 013. Two raw-SQL statements still sayrelease_groups; thebackfill has failed on its first statement on every launch since
e7748f1.Android: SQLite has no temp directory, so the champion index never builds.disk I/O error (6410)decodes toSQLITE_IOERR_GETTEMPPATH; the device has no/tmpand the app'sprocess has no
TMPDIR.Closes #160