chore(nests): instrument listener audio pipeline with NestsTrace

Adds four trace points on the listener pipeline so an end-to-end JSONL
capture (`adb logcat -s NestsTraceJsonl:D -v raw > nest-trace.jsonl`)
shows wall-clock latency at every stage:

  frame_received       (MoqLiteSession.drainOneGroup, after trySend)
  frame_object_mapped  (MoqLiteNestsListener.wrapSubscription map)
  pcm_decoded          (NestPlayer.play, after decoder.decode)
  pcm_enqueued         (NestPlayer.play, after player.enqueue)

Each event carries (sub_id, group_seq, ...) or (track_alias, obj_id, ...)
so the same frame can be followed through all four stages. Deltas
isolate which segment owns the observed startup-only ~1s lag:

  subscribe_send → first frame_received : relay forward latency
  frame_received → pcm_decoded          : Opus decode wall-time
  pcm_decoded   → pcm_enqueued          : AudioTrack ring backpressure
  pcm_enqueued  → next pcm_decoded      : decode-loop scheduling

Tracing auto-enables on debug builds when `NestActivity` opens and
disables on `onDestroy` so release apps pay only the field-load
guard inside `NestsTrace.emit`. Capture instructions are inline at
the call site in `NestActivity.onCreate`.
This commit is contained in:
Claude
2026-05-13 23:09:31 +00:00
parent dbd7266d8f
commit 86c66920d3
4 changed files with 70 additions and 1 deletions
@@ -135,10 +135,24 @@ class MoqLiteNestsListener internal constructor(
val mapped =
handle.frames.map { frame ->
val payload = if (stripLegacyTimestamp) stripLegacyTimestampPrefix(frame.payload) else frame.payload
val objId = objectIdSeq.getAndIncrement()
// Second stage of the listener-pipeline trace. Bridges
// `frame_received` (subscribeId + groupSequence + frame_idx)
// to `pcm_decoded` / `pcm_enqueued` (which know obj_id but
// not the per-group frame_idx). A gap between
// `frame_received` and `frame_object_mapped` of the same
// (sub_id, group_seq) means the consumer of the per-subscription
// Channel is slow — i.e. NestPlayer's decode/enqueue is the
// bottleneck.
com.vitorpamplona.nestsclient.trace.NestsTrace
.emit("frame_object_mapped") {
"\"sub_id\":${handle.id},\"group_seq\":${frame.groupSequence}," +
"\"obj_id\":$objId,\"size\":${payload.size}"
}
MoqObject(
trackAlias = handle.id,
groupId = frame.groupSequence,
objectId = objectIdSeq.getAndIncrement(),
objectId = objId,
publisherPriority = MoqLiteSession.DEFAULT_PRIORITY,
payload = payload,
)
@@ -277,6 +277,16 @@ class NestPlayer(
} else {
decodedFrames += 1
onLevel(peakAmplitude(pcm))
// Third stage of the listener-pipeline trace.
// Delta from `frame_object_mapped` to here is
// Opus decode wall-time (typically <1ms — a
// larger value means MediaCodec is contending).
com.vitorpamplona.nestsclient.trace.NestsTrace
.emit("pcm_decoded") {
"\"track_alias\":${obj.trackAlias},\"group\":${obj.groupId}," +
"\"obj_id\":${obj.objectId},\"samples\":${pcm.size}," +
"\"preroll_size\":${preroll.size},\"playback_begun\":$playbackBegun"
}
if (playbackBegun) {
val enqueueStart = System.currentTimeMillis()
player.enqueue(pcm)
@@ -287,6 +297,21 @@ class NestPlayer(
"NestPlayer enqueued #$enqueued (took ${enqueueMs}ms)"
}
}
// Fourth stage of the listener-pipeline
// trace. Delta from `pcm_decoded` to here
// = AudioTrack ring-buffer backpressure:
// `WRITE_BLOCKING` parks until the ring
// has room. A consistent ~20ms means the
// ring is full and the device clock is
// the pacer (healthy steady-state). A
// larger value means GC / Compose stalls
// are starving the audio-priority writer.
com.vitorpamplona.nestsclient.trace.NestsTrace
.emit("pcm_enqueued") {
"\"track_alias\":${obj.trackAlias},\"group\":${obj.groupId}," +
"\"obj_id\":${obj.objectId},\"samples\":${pcm.size}," +
"\"write_ms\":$enqueueMs"
}
} else {
preroll.addLast(pcm)
if (preroll.size >= prerollFrames) {
@@ -676,6 +676,19 @@ class MoqLiteSession internal constructor(
),
)
if (!sent.isSuccess) trySendFailures += 1
// Per-frame timestamp at the moq-lite layer — first
// stage of the listener-pipeline trace. Pair with
// `frame_object_mapped` (NestsListener), `pcm_decoded`
// (NestPlayer), and `pcm_enqueued` (NestPlayer) to
// reconstruct end-to-end glass-to-glass latency.
// `frame_idx` is the 0-based index of this frame
// within the group so DROP_OLDEST gaps downstream
// are visible as missing indices in pcm_decoded.
NestsTrace.emit("frame_received") {
"\"sub_id\":$subscribeId,\"group_seq\":$groupSequence," +
"\"frame_idx\":$frameCount,\"size\":${frame.size}," +
"\"queued\":${sent.isSuccess}"
}
}
frameCount += 1
}