Browse Source

Move AudioTrack diagnostic queries off playback and time operations separately

master
evgeny 5 days ago
parent
commit
b51e2c0817
  1. 71
      tools/chatgui-android/app/src/main/java/com/utun/chat/data/CallAudioEngine.kt
  2. 39
      tools/chatgui-android/app/src/main/java/com/utun/chat/data/CallAudioTrace.kt
  3. 30
      tools/chatgui-android/app/src/test/java/com/utun/chat/data/CallAudioTraceTest.kt

71
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)
}

39
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(",") })

30
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<String>()
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<String>()
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") })
}
}

Loading…
Cancel
Save