diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/screen/loggedIn/nests/room/activity/NestActivity.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/screen/loggedIn/nests/room/activity/NestActivity.kt index 1ff53d481..2430c89f2 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/screen/loggedIn/nests/room/activity/NestActivity.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/screen/loggedIn/nests/room/activity/NestActivity.kt @@ -121,6 +121,19 @@ class NestActivity : AppCompatActivity() { override fun onCreate(savedInstanceState: Bundle?) { super.onCreate(savedInstanceState) + // Auto-enable NestsTrace JSONL recording for debug builds the + // moment the room activity opens. Release builds keep tracing + // off (the field load + branch in `NestsTrace.emit` is the only + // cost). The capture is bounded by the activity lifetime: the + // `setRecording(false)` in onDestroy stops further emits when + // the user leaves the room. Capture from a connected device: + // adb logcat -c + // adb logcat -s NestsTraceJsonl:D -v raw > nest-trace.jsonl + if (com.vitorpamplona.amethyst.BuildConfig.DEBUG) { + com.vitorpamplona.nestsclient.trace.NestsTrace + .setRecording(true) + } + val accountViewModel = NestBridge.accountViewModel val addressValue = intent.getStringExtra(EXTRA_ADDRESS) if (accountViewModel == null || addressValue == null) { @@ -296,6 +309,10 @@ class NestActivity : AppCompatActivity() { override fun onDestroy() { runCatching { unregisterReceiver(pipReceiver) } + if (com.vitorpamplona.amethyst.BuildConfig.DEBUG) { + com.vitorpamplona.nestsclient.trace.NestsTrace + .setRecording(false) + } super.onDestroy() } diff --git a/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/MoqLiteNestsListener.kt b/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/MoqLiteNestsListener.kt index 424ad38d9..62726b0ad 100644 --- a/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/MoqLiteNestsListener.kt +++ b/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/MoqLiteNestsListener.kt @@ -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, ) diff --git a/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/audio/NestPlayer.kt b/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/audio/NestPlayer.kt index 84b33f67e..7da451b6b 100644 --- a/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/audio/NestPlayer.kt +++ b/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/audio/NestPlayer.kt @@ -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) { diff --git a/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/moq/lite/MoqLiteSession.kt b/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/moq/lite/MoqLiteSession.kt index be47b28ba..e5c997b7c 100644 --- a/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/moq/lite/MoqLiteSession.kt +++ b/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/moq/lite/MoqLiteSession.kt @@ -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 }