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 1c4f4d1c..a123103d 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 @@ -427,9 +427,12 @@ class CallAudioEngine { private fun playLoop() { val trace = CallAudioTrace(callId) { level, message -> LogManager.addLog(level, "call", message) } + val track = audioTrack ?: return val reporter = Thread({ try { + val stamp = AudioTimestamp() while (!Thread.currentThread().isInterrupted) { + if (trace.enabled && active) trace.device = samplePlaybackDevice(track, stamp) trace.flush() Thread.sleep(200) } @@ -443,7 +446,34 @@ class CallAudioEngine { } }, "utun-call-diagnostics").apply { start() } try { playLoop(trace) } - finally { reporter.interrupt(); reporter.join() } + finally { + reporter.interrupt() + // Android-запрос может не прерываться; release AudioTrack ждёт завершения reporter. + var interrupted = Thread.interrupted() + while (reporter.isAlive) { + try { reporter.join() } + catch (_: InterruptedException) { interrupted = true } + } + if (interrupted) Thread.currentThread().interrupt() + } + } + + /** Только reporter: Binder/внутренние locks AudioTrack не должны вызываться здесь из playback. */ + private fun samplePlaybackDevice(track: AudioTrack, stamp: AudioTimestamp): CallAudioTrace.DeviceSample { + val beginNs = System.nanoTime() + val stampOk = track.getTimestamp(stamp) + val stampEndNs = System.nanoTime() + val route = track.routedDevice + val routeEndNs = System.nanoTime() + val underruns = track.underrunCount.toLong() + val bufferFrames = track.bufferSizeInFrames.toLong() + val startFrames = if (Build.VERSION.SDK_INT >= 31) track.startThresholdInFrames.toLong() else bufferFrames + val endNs = System.nanoTime() + return CallAudioTrace.DeviceSample( + route?.id?.toLong() ?: -1, route?.type?.toLong() ?: -1, underruns, bufferFrames, startFrames, + if (stampOk) stamp.framePosition else -1, if (stampOk) stamp.nanoTime else -1, stampOk, + beginNs / 1000, endNs / 1000, (stampEndNs - beginNs) / 1000, + (routeEndNs - stampEndNs) / 1000, (endNs - routeEndNs) / 1000) } private fun playLoop(trace: CallAudioTrace) { @@ -462,15 +492,14 @@ class CallAudioEngine { var clockFailed = false val diagnostic = LongArray(8) val row = LongArray(CallAudioTrace.WIDTH) - val stamp = AudioTimestamp() - var stampAtUs = 0L - var stampOk = false while (active) { val track = audioTrack ?: return val pullAtNs = System.nanoTime() val n = NativeLib.callAudioPull(callId, buf) - val pullUs = (System.nanoTime() - pullAtNs) / 1000 + val pullEndNs = System.nanoTime() + val pullUs = (pullEndNs - pullAtNs) / 1000 trace.enabled = NativeLib.callAudioDiagnostics(callId, diagnostic) + val diagnosticUs = (System.nanoTime() - pullEndNs) / 1000 if (n !in 0..FRAME_SAMPLES) { reportFailure(callId, "callAudioPull=$n expected=0..$FRAME_SAMPLES") return @@ -482,8 +511,13 @@ class CallAudioEngine { var zeroWrites = 0L var observedPlayed = -1L val writeAtNs = System.nanoTime() + var writeCallNs = 0L + var headCallNs = 0L + var progressCallNs = 0L while (active && offset < FRAME_SAMPLES) { + var operationNs = System.nanoTime() val written = track.write(silence, offset, FRAME_SAMPLES - offset, AudioTrack.WRITE_NON_BLOCKING) + writeCallNs += System.nanoTime() - operationNs if (written < 0) { reportFailure(callId, "AudioTrack.write=$written offset=$offset state=${track.playState}") return @@ -503,10 +537,15 @@ class CallAudioEngine { playFramesWritten += written } val nowUs = System.nanoTime() / 1000 - val played = head.update(track.playbackHeadPosition, playFramesWritten) + operationNs = System.nanoTime() + val position = track.playbackHeadPosition + headCallNs += System.nanoTime() - operationNs + val played = head.update(position, playFramesWritten) if (played != null) { observedPlayed = played + operationNs = System.nanoTime() NativeLib.callAudioProgress(callId, epoch, played, nowUs) + progressCallNs += System.nanoTime() - operationNs } else if (!clockFailed) { clockFailed = true // Отрицательная позиция немедленно инвалидирует снимок в native. @@ -515,22 +554,18 @@ class CallAudioEngine { "playback clock invalid id=$callId epoch=$epoch written=$playFramesWritten; audio continues") } } - val writeUs = (System.nanoTime() - writeAtNs) / 1000 + val writeSpanUs = (System.nanoTime() - writeAtNs) / 1000 if (trace.enabled && active) { + val device = trace.device val nowUs = System.nanoTime() / 1000 - if (nowUs - stampAtUs >= 200_000) { - stampAtUs = nowUs - stampOk = track.getTimestamp(stamp) - } - val route = track.routedDevice - row[0] = nowUs; row[1] = route?.id?.toLong() ?: -1; row[2] = route?.type?.toLong() ?: -1 + device.copyTo(row) + row[0] = nowUs row[3] = playFramesWritten; row[4] = observedPlayed - row[5] = pullUs; row[6] = writeUs; row[7] = ((pullAtNs - nextNs) / 1000).coerceAtLeast(0) - row[8] = zeroWrites; row[9] = track.underrunCount.toLong(); row[10] = track.bufferSizeInFrames.toLong() - row[11] = if (Build.VERSION.SDK_INT >= 31) track.startThresholdInFrames.toLong() else row[10] - row[12] = if (stampOk) stamp.framePosition else -1; row[13] = if (stampOk) stamp.nanoTime else -1 - row[14] = stampAtUs; row[15] = if (stampOk) 1 else 0 + row[5] = pullUs; row[6] = writeCallNs / 1000; row[7] = ((pullAtNs - nextNs) / 1000).coerceAtLeast(0) + row[8] = zeroWrites diagnostic.copyInto(row, 16); row[24] = offset.toLong() + row[25] = headCallNs / 1000; row[26] = progressCallNs / 1000; row[27] = writeSpanUs + row[28] = diagnosticUs; row[29] = nowUs - pullAtNs / 1000 trace.record(row) } diff --git a/tools/chatgui-android/app/src/main/java/com/utun/chat/data/CallAudioTrace.kt b/tools/chatgui-android/app/src/main/java/com/utun/chat/data/CallAudioTrace.kt index 472a3995..2b1f5a00 100644 --- a/tools/chatgui-android/app/src/main/java/com/utun/chat/data/CallAudioTrace.kt +++ b/tools/chatgui-android/app/src/main/java/com/utun/chat/data/CallAudioTrace.kt @@ -3,15 +3,34 @@ package com.utun.chat.data /** Только числа в playback-потоке; форматирование и вывод выполняет отдельный reporter. */ internal class CallAudioTrace(private val id: Long, private val emit: (String, String) -> Unit) { companion object { - const val WIDTH = 25 + const val WIDTH = 35 const val CAPACITY = 512 - // monoUs, routeId, routeType, written, played, pullUs, writeUs, wakeLateUs, zeroWrites, + // monoUs, routeId, routeType, written, played, pullUs, writeCallUs, wakeLateUs, zeroWrites, // deviceUnderruns, bufferFrames, startFrames, stampFrame, stampNs, stampReadUs, stampOk, // encodedMs, processingMs, reserveMs, spreadMs, pcmSamples, tempo100, jbUnderruns, waiting, accepted + // headCallUs, progressCallUs, writeSpanUs, jbSnapshotUs, blockUs, + // deviceBeginUs, deviceEndUs, stampQueryUs, routeQueryUs, propertiesQueryUs private const val PRE_US = 2_000_000L private const val POST_US = 3_000_000L } @Volatile var enabled = false + /** Неизменяемый снимок reporter; playback только читает ссылку, не вызывает Android API. */ + data class DeviceSample( + val routeId: Long = -1, val routeType: Long = -1, val underruns: Long = -1, + val bufferFrames: Long = -1, val startFrames: Long = -1, + val stampFrame: Long = -1, val stampNs: Long = -1, val stampOk: Boolean = false, + val beginUs: Long = -1, val endUs: Long = -1, + val stampQueryUs: Long = 0, val routeQueryUs: Long = 0, val propertiesQueryUs: Long = 0 + ) { + fun copyTo(row: LongArray) { + row[1] = routeId; row[2] = routeType; row[9] = underruns + row[10] = bufferFrames; row[11] = startFrames + row[12] = stampFrame; row[13] = stampNs; row[14] = beginUs; row[15] = if (stampOk) 1 else 0 + row[30] = beginUs; row[31] = endUs + row[32] = stampQueryUs; row[33] = routeQueryUs; row[34] = propertiesQueryUs + } + } + @Volatile var device = DeviceSample() private val ring = Array(CAPACITY) { LongArray(WIDTH) } private var head = 0 private var count = 0 @@ -66,13 +85,13 @@ internal class CallAudioTrace(private val id: Long, private val emit: (String, S history.addLast(row) while (history.size > 400 || (eventAt < 0 && history.first()[0] < now - PRE_US)) history.removeFirst() var events = if (old == null) 1 else 0 - if (old != null && (row[1] != old[1] || row[2] != old[2])) events = events or 2 + if (old != null && old[1] >= 0 && row[1] >= 0 && (row[1] != old[1] || row[2] != old[2])) events = events or 2 val queueUs = queued(row) if (queueUs > 100_000) { if (highSince < 0) highSince = now } else highSince = -1 if (old != null && row[4] == old[4] && queueUs > 0) { if (stoppedSince < 0) stoppedSince = old[0] } else stoppedSince = -1 - if (old != null && row[9] > old[9]) underrunAt = now + if (old != null && old[9] >= 0 && row[9] > old[9]) underrunAt = now val current = (if (highSince >= 0 && now - highSince >= 1_000_000) 4 else 0) or (if (stoppedSince >= 0 && now - stoppedSince >= 100_000) 8 else 0) or (if (now - underrunAt < 3_000_000) 16 else 0) @@ -111,11 +130,15 @@ internal class CallAudioTrace(private val id: Long, private val emit: (String, S emit("DEBUG", "audio summary call=$id monoUs=${last[0]} spanUs=${last[0] - first[0]} n=${summary.size} " + "route=${last[1]}/${last[2]} min/avg/max queueUs=${range(::queued)} " + "jbMs=${range { it[16] + it[17] }} reserveMs=${range { it[18] }} spreadMs=${range { it[19] }} " + - "pullUs=${range { it[5] }} writeUs=${range { it[6] }} wakeLateUs=${range { it[7] }} " + + "pullUs=${range { it[5] }} writeCallUs=${range { it[6] }} headCallUs=${range { it[25] }} " + + "progressCallUs=${range { it[26] }} writeSpanUs=${range { it[27] }} jbSnapshotUs=${range { it[28] }} " + + "blockUs=${range { it[29] }} wakeLateUs=${range { it[7] }} " + "tempo=${last[21]} deviceUnderruns=${last[9]} deviceUnderDelta=${last[9] - reportedDeviceUnderruns} " + "jbUnderruns=${last[22]} jbUnderDelta=${last[22] - reportedJbUnderruns} " + "zeroWrites=${summary.sumOf { it[8] }} missingPcm=${summary.sumOf { (960 - it[20]).coerceAtLeast(0) }} " + "stamp=${last[12]}@${last[13]} readUs=${last[14]} ok=${last[15]} " + + "deviceAgeUs=${if (last[31] >= 0) last[0] - last[31] else -1} " + + "stampQueryUs=${range { it[32] }} routeQueryUs=${range { it[33] }} propertiesQueryUs=${range { it[34] }} " + "buffer=${last[10]} start=${last[11]} fault=$faults suppressed=$suppressed") reportedDeviceUnderruns = last[9]; reportedJbUnderruns = last[22] summary.clear() @@ -124,9 +147,11 @@ internal class CallAudioTrace(private val id: Long, private val emit: (String, S private fun dump(partial: Boolean) { emit("DEBUG", "audio detail call=$id triggerUs=$eventAt reasons=$eventBits events=$eventCount partial=$partial " + "bits=start:1,route:2,queue:4,stalled:8,underrun:16 " + - "columns=monoUs,routeId,routeType,written,played,pullUs,writeUs,wakeLateUs,zeroWrites,deviceUnderruns," + + "columns=monoUs,routeId,routeType,written,played,pullUs,writeCallUs,wakeLateUs,zeroWrites,deviceUnderruns," + "bufferFrames,startFrames,stampFrame,stampNs,stampReadUs,stampOk," + - "encodedMs,processingMs,reserveMs,spreadMs,pcmSamples,tempo100,jbUnderruns,waiting,accepted") + "encodedMs,processingMs,reserveMs,spreadMs,pcmSamples,tempo100,jbUnderruns,waiting,accepted," + + "headCallUs,progressCallUs,writeSpanUs,jbSnapshotUs,blockUs," + + "deviceBeginUs,deviceEndUs,stampQueryUs,routeQueryUs,propertiesQueryUs") // До пяти секунд, по четыре снимка в строке, с явным временем каждого. history.filter { it[0] in (eventAt - PRE_US)..(eventAt + POST_US) }.chunked(4).forEach { group -> emit("DEBUG", "audio detail call=$id rows=" + group.joinToString(";") { it.joinToString(",") }) diff --git a/tools/chatgui-android/app/src/test/java/com/utun/chat/data/CallAudioTraceTest.kt b/tools/chatgui-android/app/src/test/java/com/utun/chat/data/CallAudioTraceTest.kt index d207817c..d3271274 100644 --- a/tools/chatgui-android/app/src/test/java/com/utun/chat/data/CallAudioTraceTest.kt +++ b/tools/chatgui-android/app/src/test/java/com/utun/chat/data/CallAudioTraceTest.kt @@ -61,4 +61,34 @@ class CallAudioTraceTest { trace.record(sample(40_000)); trace.flush(true) assertTrue(logs.isEmpty()) } + + @Test fun deviceSnapshotKeepsItsOwnQueryTimesAndDoesNotOverwritePlaybackMeasurements() { + val logs = mutableListOf() + val trace = CallAudioTrace(5) { _, text -> logs.add(text) }.apply { enabled = true } + val row = sample(1_000_000) + row[6] = 11; row[25] = 22; row[26] = 33; row[27] = 90; row[28] = 44; row[29] = 150 + trace.device = CallAudioTrace.DeviceSample(3, 2, 0, 7696, 1920, 48000, 900_000_000, true, + 900_000, 950_000, 10_000, 30_000, 10_000) + val saved = trace.device + trace.device = CallAudioTrace.DeviceSample() // Уже захваченный снимок остаётся неизменным. + saved.copyTo(row) + trace.record(row); trace.flush(true) + val summary = logs.first { it.contains("audio summary") } + assertTrue(summary.contains("writeCallUs=11/11/11 headCallUs=22/22/22 progressCallUs=33/33/33")) + assertTrue(summary.contains("writeSpanUs=90/90/90 jbSnapshotUs=44/44/44 blockUs=150/150/150")) + assertTrue(summary.contains("deviceAgeUs=50000 stampQueryUs=10000/10000/10000 routeQueryUs=30000/30000/30000")) + assertEquals(900_000L, row[14]); assertEquals(950_000L, row[31]) + } + + @Test fun firstDeviceSnapshotIsNotReportedAsRouteChangeOrUnderrun() { + val logs = mutableListOf() + val trace = CallAudioTrace(6) { _, text -> logs.add(text) }.apply { enabled = true } + val first = sample(0) + CallAudioTrace.DeviceSample().copyTo(first) + trace.record(first) + trace.record(sample(20_000)) + trace.flush(true) + assertTrue(logs.any { it.contains("reasons=1 events=1") }) + assertFalse(logs.any { it.contains(" fault=") && it.contains("audio trace") }) + } }