diff --git a/tools/chatgui-android/app/src/main/java/com/utun/chat/data/CallAudioEngine.kt b/tools/chatgui-android/app/src/main/java/com/utun/chat/data/CallAudioEngine.kt index c3fb2e13..0fb97d72 100644 --- a/tools/chatgui-android/app/src/main/java/com/utun/chat/data/CallAudioEngine.kt +++ b/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 } diff --git a/tools/chatgui/src/voice_audio_io.cpp b/tools/chatgui/src/voice_audio_io.cpp index 9ed7008a..1bb89af7 100644 --- a/tools/chatgui/src/voice_audio_io.cpp +++ b/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); }