Measure Android capture age and device startup stages

tools/chatgui-android/app/src/main/java/com/utun/chat/data/CallAudioEngine.kt

@@ -191,21 +191,28 @@ class CallAudioEngine {
                         reportFailure(id, "AudioTrack.getMinBufferSize=$trackMin")
                         return@runWorker
                     }
+                    val minQueryMs = SystemClock.elapsedRealtime() - createdAt
                     val trackBuf = (trackMin * 2).coerceAtLeast(FRAME_SAMPLES * 4)
+                    val constructorAt = SystemClock.elapsedRealtime()
                     val track = AudioTrack(
                         AudioAttributes.Builder().setUsage(AudioAttributes.USAGE_VOICE_COMMUNICATION)
                             .setContentType(AudioAttributes.CONTENT_TYPE_SPEECH).build(),
                         AudioFormat.Builder().setSampleRate(SAMPLE_RATE).setEncoding(AudioFormat.ENCODING_PCM_16BIT)
                             .setChannelMask(AudioFormat.CHANNEL_OUT_MONO).build(),
                         trackBuf, AudioTrack.MODE_STREAM, AudioManager.AUDIO_SESSION_ID_GENERATE)
+                    val constructorMs = SystemClock.elapsedRealtime() - constructorAt
                     audioTrack = track
                     if (!active) return@runWorker
                     if (track.state != AudioTrack.STATE_INITIALIZED) {
                         reportFailure(id, "AudioTrack not initialized state=${track.state}")
                         return@runWorker
                     }
+                    val routingAt = SystemClock.elapsedRealtime()
                     applyTrackOutputDevice(router.currentOutputDevice)
+                    val routingMs = SystemClock.elapsedRealtime() - routingAt
+                    val bufferAt = SystemClock.elapsedRealtime()
                     configurePlaybackBuffer(track, "start")
+                    val bufferMs = SystemClock.elapsedRealtime() - bufferAt
                     track.addOnRoutingChangedListener(trackRouteListener, mainHandler)
                     val trackCreateMs = SystemClock.elapsedRealtime() - createdAt
                     val playedAt = SystemClock.elapsedRealtime()
@@ -219,6 +226,7 @@ class CallAudioEngine {
                     LogManager.addLog("INFO", "CallAudio",
                         "playback started id=$id totalMs=${SystemClock.elapsedRealtime() - startElapsedMs} " +
                             "trackCreateMs=$trackCreateMs trackStartMs=${SystemClock.elapsedRealtime() - playedAt} " +
+                            "minQueryMs=$minQueryMs constructorMs=$constructorMs routingMs=$routingMs bufferMs=$bufferMs " +
                             "trackBuf=$trackBuf captureReady=$captureReady")
                 }
                 mainHandler.post(ready)
@@ -338,6 +346,9 @@ class CallAudioEngine {
         val clock = CallCaptureClock()
         val stamp = AudioTimestamp()
         var loggedMeasured: Boolean? = null
+        var reportNs = System.nanoTime()
+        var ageLow = Long.MAX_VALUE; var ageHigh = Long.MIN_VALUE; var ageSum = 0L
+        var ageCount = 0; var measuredCount = 0
         while (active) {
             /* проводная гарнитура появилась/исчезла — меняем источник захвата */
             if (wantedWired != wiredActive) {
@@ -399,9 +410,19 @@ class CallAudioEngine {
                     "capture clock id=$callId measured=${clock.measured} frame=$capFramesRead ptsUs=$ptsUs")
             }
             capFramesRead += FRAME_SAMPLES
+            val feedAt = System.nanoTime()
+            val ageUs = feedAt / 1000 - ptsUs
+            ageLow = minOf(ageLow, ageUs); ageHigh = maxOf(ageHigh, ageUs); ageSum += ageUs; ageCount++
+            if (clock.measured) measuredCount++
             if (!NativeLib.callAudioFeed(callId, out, ptsUs)) {
                 LogManager.addLog("WARN", "CallAudio", "callAudioFeed returned false")
             }
+            if (feedAt - reportNs >= 1_000_000_000) {
+                LogManager.addLog("DEBUG", "call", "audio capture latency id=$callId frames=$ageCount measured=$measuredCount " +
+                    "firstSampleAgeUs=$ageLow/${ageSum / ageCount}/$ageHigh")
+                reportNs = feedAt; ageLow = Long.MAX_VALUE; ageHigh = Long.MIN_VALUE; ageSum = 0
+                ageCount = 0; measuredCount = 0
+            }
         }
     }
 
@@ -417,12 +438,15 @@ class CallAudioEngine {
      *  микрофон проводной гарнитуры; AudioSource.MIC на ней даёт тишину). Для проводной
      *  гарнитуры дополнительно роутим setPreferredDevice на её микрофон. */
     private fun createAudioRecord(wired: Boolean): AudioRecord? {
+        val queryAt = SystemClock.elapsedRealtime()
         val recMin = AudioRecord.getMinBufferSize(
             SAMPLE_RATE, AudioFormat.CHANNEL_IN_MONO, AudioFormat.ENCODING_PCM_16BIT)
+        val queryMs = SystemClock.elapsedRealtime() - queryAt
         if (recMin <= 0) {
             LogManager.addLog("ERROR", "CallAudio", "AudioRecord.getMinBufferSize=$recMin wired=$wired")
             return null
         }
+        val constructorAt = SystemClock.elapsedRealtime()
         val rec = try {
             AudioRecord(
                 MediaRecorder.AudioSource.VOICE_COMMUNICATION,
@@ -432,11 +456,13 @@ class CallAudioEngine {
             LogManager.addLog("ERROR", "CallAudio", "AudioRecord create failed (wired=$wired): ${e.message}")
             return null
         }
+        val constructorMs = SystemClock.elapsedRealtime() - constructorAt
         if (rec.state != AudioRecord.STATE_INITIALIZED) {
             LogManager.addLog("ERROR", "CallAudio", "AudioRecord not initialized (wired=$wired)")
             rec.release()
             return null
         }
+        val routeAt = SystemClock.elapsedRealtime()
         if (wired) {
             val dev = router.wiredInputDevice()
             val ok = try {
@@ -450,6 +476,8 @@ class CallAudioEngine {
         } else {
             LogManager.addLog("WARN", "CallAudio", "record input -> VOICE_COMMUNICATION (default)")
         }
+        LogManager.addLog("INFO", "CallAudio", "capture device ready id=$callId minQueryMs=$queryMs constructorMs=$constructorMs " +
+            "routingMs=${SystemClock.elapsedRealtime() - routeAt} minBytes=$recMin")
         return rec
     }
 

tools/chatgui/src/voice_audio_io.cpp

@@ -223,7 +223,7 @@ void VoiceAudioIo::playbackLoop() {
                 int count = std::clamp(call_audio_pull_pcm(m_session, mono, 960), 0, 960);
                 for (int i = 0; i < count; ++i) block.pcm[2*i] = block.pcm[2*i+1] = mono[i];
             } else radio_audio_pull_pcm(m_session, block.pcm, 1920);
-            pullUs.add(voice_time_us() - pullAt);
+            if (m_kind == Kind::Call) pullUs.add(voice_time_us() - pullAt);
             position += 960;
             if (!m_playback.push(block)) DEBUG_WARN(DEBUG_CATEGORY_CALL, "voice-io: playback queue contention");
         } else {
@@ -466,7 +466,7 @@ void VoiceAudioIo::captureLoop() {
                 }
             }
             referenceAvailable = available;
-            prepareUs.add(voice_time_us() - prepareAt);
+            if (m_kind == Kind::Call) prepareUs.add(voice_time_us() - prepareAt);
             deliver(960);
         }