Remove Android video timing probes and categorize radio logs

This commit is contained in:
evgeny committed 2026-10-18 15:10:06 +02:00
1 parent 044a20d4a0
commit 0e2253cdc8
3 files changed
+12 -57

No files matched your search

@@ -1,9 +1,6 @@
package com.utun.chat.data
import android.media.MediaCodec
import android.os.Handler
import android.os.Looper
import android.os.SystemClock
import android.view.Surface
import kotlinx.coroutines.flow.MutableStateFlow
import kotlinx.coroutines.flow.StateFlow
@@ -42,7 +39,6 @@ internal class CallVideoPlayer(private val id: Long, private val failure: (Strin
var reportedGeneration = 0L; var rejectedGeneration = 0L
var reportAt = System.nanoTime(); var pulled = 0; var queued = 0; var decoded = 0; var rendered = 0; var late = 0
val clock = LongArray(8); val info = MediaCodec.BufferInfo()
val renderHandler = Handler(Looper.getMainLooper())
fun close() {
try { decoder?.stop() } catch (e: Exception) { LogManager.addLog("WARN", "call", "video decoder stop: ${e.message}") }
try { decoder?.release() } catch (e: Exception) { LogManager.addLog("WARN", "call", "video decoder release: ${e.message}") }
@@ -76,9 +72,6 @@ internal class CallVideoPlayer(private val id: Long, private val failure: (Strin
val timing = checkNotNull(inputs.pollFirst()) { "Video output without input timing" }
check(timing.pts == info.presentationTimeUs) { "Video output timing mismatch" }
lastOutput = info.presentationTimeUs; pictures.addLast(Picture(out, timing))
if (timing.pts % 1_000_000 < 34_000) LogManager.addLog("DEBUG", "debug",
"video timing stage=decode call=$id pts=${timing.pts} mono_us=${System.nanoTime() / 1000} " +
"received_us=${timing.received} inflight=${inputs.size}")
decoded++
}
} else if (out == MediaCodec.INFO_OUTPUT_FORMAT_CHANGED) {
@@ -93,9 +86,6 @@ internal class CallVideoPlayer(private val id: Long, private val failure: (Strin
if (decision > 0) wakeUs = now / 1000 + decision
else if (first != null) {
val render = decision == 0L
if (first.timing.pts % 1_000_000 < 34_000) LogManager.addLog("DEBUG", "debug",
"video timing stage=release call=$id pts=${first.timing.pts} mono_us=${System.nanoTime() / 1000} " +
"audio_pts=${clock[4]} render=$render decision=$decision")
decoder!!.releaseOutputBuffer(first.index, render); pictures.removeFirst(); worked = true
if (render) {
rendered++
@@ -112,9 +102,6 @@ internal class CallVideoPlayer(private val id: Long, private val failure: (Strin
// Ожидание срока output не останавливает подачу input; очередь остаётся ограниченной.
if (pending == null && inputs.size + pictures.size < 8) {
pending = CallVideoNative.pull(id, meta); if (pending != null) pulled++
if (pending != null && meta[10] % 1_000_000 < 34_000) LogManager.addLog("DEBUG", "debug",
"video timing stage=pull call=$id frame=${meta[9]} pts=${meta[10]} mono_us=${System.nanoTime() / 1000} " +
"boot_us=${SystemClock.elapsedRealtimeNanos() / 1000} audio_pts=${clock[4]} audio_valid=$valid")
}
val data = pending
if (data != null && surface?.isValid == true) {
@@ -135,12 +122,6 @@ internal class CallVideoPlayer(private val id: Long, private val failure: (Strin
check(implementation.profiles and next.profile != 0) { "Unsupported decoder profile" }
decoder = MediaCodec.createByCodecName(implementation.name)
decoder!!.configure(type.decoderFormat(next.width, next.height, next.rotation, config), surface, null, 0)
decoder!!.setOnFrameRenderedListener({ _, pts, at ->
// На некоторых SurfaceTexture backend at повторяет PTS: логируем как reported, не как доказанное время показа.
if (running && pts % 1_000_000 < 34_000) LogManager.addLog("DEBUG", "debug",
"video timing stage=surface call=$id generation=${next.generation} pts=$pts " +
"reported_us=${at / 1000} callback_us=${System.nanoTime() / 1000}")
}, renderHandler)
decoder!!.start(); format = next; lastProgress = System.nanoTime()
LogManager.addLog("INFO", "call", "video decoder started call=$id codec=${implementation.name} format=$next")
}
@@ -152,8 +133,6 @@ internal class CallVideoPlayer(private val id: Long, private val failure: (Strin
} else data
val buffer = checkNotNull(decoder!!.getInputBuffer(index)); check(bytes.size <= buffer.capacity())
buffer.put(bytes); decoder!!.queueInputBuffer(index, 0, bytes.size, meta[10], 0)
if (meta[10] % 1_000_000 < 34_000) LogManager.addLog("DEBUG", "debug",
"video timing stage=queue call=$id frame=${meta[9]} pts=${meta[10]} mono_us=${System.nanoTime() / 1000}")
inputs.addLast(Timing(meta[10], meta[12])); pending = null; queued++; worked = true
}
}
@@ -114,7 +114,7 @@ class RadioAudioEngine {
private val vadTimeout = Runnable {
io.execute {
if (active && vadWindow.deadlineMs > 0L && !vadWindow.isAllowed(SystemClock.elapsedRealtime())) {
LogManager.addLog("INFO", "debug", "Auto background window expired (15 minutes) group=$audioGroup")
LogManager.addLog("INFO", "radio", "Auto background window expired (15 minutes) group=$audioGroup")
updateCapture()
}
}
@@ -231,7 +231,7 @@ class RadioAudioEngine {
val nowMs = SystemClock.elapsedRealtime()
io.execute {
vadWindow.setForeground(foreground, nowMs)
LogManager.addLog("DEBUG", "debug", "Auto application foreground=$foreground group=$audioGroup " +
LogManager.addLog("DEBUG", "radio", "Auto application foreground=$foreground group=$audioGroup " +
"backgroundLeftMs=${vadWindow.timeLeftMs(nowMs)}")
if (active) updateCapture()
}
@@ -435,11 +435,11 @@ class RadioAudioEngine {
if (!active || generation != version) return@execute
if (intent.action == Intent.ACTION_SCREEN_OFF) {
vadWindow.close()
LogManager.addLog("INFO", "debug", "Auto screen off: window closed group=$audioGroup")
LogManager.addLog("INFO", "radio", "Auto screen off: window closed group=$audioGroup")
}
if (intent.action == Intent.ACTION_SCREEN_ON) {
vadWindow.restart(SystemClock.elapsedRealtime())
LogManager.addLog("INFO", "debug", "Auto screen on: new background window (15 minutes) group=$audioGroup")
LogManager.addLog("INFO", "radio", "Auto screen on: new background window (15 minutes) group=$audioGroup")
}
updateCapture()
}
@@ -490,7 +490,7 @@ class RadioAudioEngine {
private fun startCapture(mode: Int): Boolean {
if (!MicrophonePermission.granted()) {
LogManager.addLog("WARN", "debug", "Auto/PTT capture blocked: RECORD_AUDIO not granted group=$audioGroup mode=$mode")
LogManager.addLog("WARN", "radio", "Auto/PTT capture blocked: RECORD_AUDIO not granted group=$audioGroup mode=$mode")
return false
}
val preferred = when (configuredInput) {
@@ -522,7 +522,7 @@ class RadioAudioEngine {
autoMode = NativeLib.radioAutoMode()
captureRequestedMode = mode
if (mode != RadioAutoSettings.OFF && autoMode == RadioAutoSettings.OFF && !requestedTalk && !levelMonitoring) {
LogManager.addLog("ERROR", "debug", "Automatic transmission unavailable: capture cancelled group=$audioGroup")
LogManager.addLog("ERROR", "radio", "Automatic transmission unavailable: capture cancelled group=$audioGroup")
NativeLib.radioCaptureStop(); subscription.close()
return false
}
@@ -565,7 +565,7 @@ class RadioAudioEngine {
captureThread = null
captureSubscription = null
NativeLib.radioCaptureStop()
LogManager.addLog("INFO", "debug", "Auto/PTT capture released group=$audioGroup")
LogManager.addLog("INFO", "radio", "Auto/PTT capture released group=$audioGroup")
}
autoMode = RadioAutoSettings.OFF
capturePttRequested = false
@@ -699,7 +699,7 @@ class RadioAudioEngine {
val feedAllowed = active && groupId == group && captureRunning &&
(talking || autoAllowed || (levelMonitoring && screenInteractive))
if (previousFeedAllowed != feedAllowed) {
LogManager.addLog("DEBUG", "debug", "Auto PCM gate group=$group frame=$frameN allowed=$feedAllowed " +
LogManager.addLog("DEBUG", "radio", "Auto PCM gate group=$group frame=$frameN allowed=$feedAllowed " +
"active=$active currentGroup=$groupId capture=$captureRunning manual=$requestedTalk talking=$talking " +
"nativeMode=$autoMode screen=$screenInteractive backgroundDeadlineMs=${vadWindow.deadlineMs}")
previousFeedAllowed = feedAllowed
@@ -711,7 +711,7 @@ class RadioAudioEngine {
maxFeedNs = maxOf(maxFeedNs, SystemClock.elapsedRealtimeNanos() - feedStartedNs)
if (fed) fedFrames++ else {
failedFrames++
if (failedFrames == 1) LogManager.addLog("WARN", "debug", "Auto/PTT PCM rejected group=$group frame=$frameN")
if (failedFrames == 1) LogManager.addLog("WARN", "radio", "Auto/PTT PCM rejected group=$group frame=$frameN")
}
if (fed && requestedTalk && requestNs != reportedRequestNs) {
reportedRequestNs = requestNs
@@ -725,8 +725,8 @@ class RadioAudioEngine {
LogManager.addLog("DEBUG", "radio", "TX state group=$group on=${transmitting != null} manual=$requestedTalk mode=$autoMode")
}
val nowMs = SystemClock.elapsedRealtime()
if (nowMs - statsMs >= 1000L) {
LogManager.addLog("DEBUG", "debug", "Auto capture summary group=$group spanMs=${nowMs - statsMs} " +
if (nowMs - statsMs >= 10_000L) {
LogManager.addLog("DEBUG", "radio", "Auto capture summary group=$group spanMs=${nowMs - statsMs} " +
"frames=$statsFrames audioMs=${statsFrames * FRAME_MS} fed=$fedFrames skipped=$skippedFrames rejected=$failedFrames " +
"rmsDb=$minRmsDb..$maxRmsDb readMaxMs=${maxReadNs / 1_000_000.0} feedMaxMs=${maxFeedNs / 1_000_000.0} " +
"channels=$ch input=$configuredInput " +
@@ -5,7 +5,6 @@ import android.content.pm.PackageManager
import android.content.Context
import android.graphics.Matrix
import android.graphics.SurfaceTexture
import android.os.Build
import android.view.Surface
import android.view.TextureView
import androidx.activity.compose.rememberLauncherForActivityResult
@@ -129,19 +128,6 @@ private class CallVideoTexture(context: Context, private val video: CallVideoEng
private var closed = false
private var format: CallVideoFormat? = null
private var large = false
private var commitPending = false
private var lastCommitPts = -1L
private val committed = Runnable {
commitPending = false
if (!closed) surfaceTexture?.let { texture ->
val pts = texture.timestamp / 1000
if (pts > 0 && pts != lastCommitPts && pts % 1_000_000 < 34_000)
com.utun.chat.data.LogManager.addLog("DEBUG", "debug",
"video timing stage=commit pts=$pts mono_us=${System.nanoTime() / 1000} generation=${format?.generation} " +
"visible=$isShown alpha=$alpha size=${width}x$height")
lastCommitPts = pts
}
}
fun update(next: CallVideoFormat?, expanded: Boolean) {
if (format == next && large == expanded) return
format = next; large = expanded; fit()
@@ -157,16 +143,7 @@ private class CallVideoTexture(context: Context, private val video: CallVideoEng
}
override fun onSurfaceTextureSizeChanged(texture: SurfaceTexture, width: Int, height: Int) { fit() }
override fun onSurfaceTextureDestroyed(texture: SurfaceTexture): Boolean { closeOutput(); return false }
override fun onSurfaceTextureUpdated(texture: SurfaceTexture) {
// applyUpdate лишь передаёт работу RenderThread: timestamp здесь ещё может принадлежать предыдущему кадру.
val pts = texture.timestamp / 1000
if (pts > 0 && pts % 1_000_000 < 34_000) com.utun.chat.data.LogManager.addLog("DEBUG", "debug",
"video timing stage=texture_update pts=$pts mono_us=${System.nanoTime() / 1000} generation=${format?.generation} " +
"visible=$isShown alpha=$alpha size=${width}x$height")
if (Build.VERSION.SDK_INT >= 29 && isHardwareAccelerated && !commitPending) {
commitPending = true; viewTreeObserver.registerFrameCommitCallback(committed)
}
}
override fun onSurfaceTextureUpdated(texture: SurfaceTexture) {}
}
}
private fun fit() {
@@ -187,7 +164,6 @@ private class CallVideoTexture(context: Context, private val video: CallVideoEng
private fun closeOutput() { attached?.let(video::detachSurface); attached = null }
fun close() {
closed = true
if (Build.VERSION.SDK_INT >= 29 && viewTreeObserver.isAlive) viewTreeObserver.unregisterFrameCommitCallback(committed)
closeOutput()
}
}