Measure Android video decode audio wait and surface presentation separately

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

@@ -1,6 +1,9 @@
 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
@@ -34,6 +37,7 @@ internal class CallVideoPlayer(private val id: Long, private val failure: (Strin
         var reportAt = System.nanoTime(); var pulled = 0; var queued = 0; var decoded = 0; var rendered = 0; var late = 0
         var maxAheadUs = 0L; var maxLateUs = 0L; var invalidClock = 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}") }
             decoder?.release(); decoder = null; format = null; held = -1; inflight = 0; draining = false; lastOutput = -1
@@ -61,6 +65,9 @@ internal class CallVideoPlayer(private val id: Long, private val failure: (Strin
                     }
                     if (held >= 0 && valid && heldPts <= clock[4]) {
                         val render = heldPts >= clock[4] - 500_000
+                        if (heldPts % 1_000_000 < 34_000) LogManager.addLog("DEBUG", "debug",
+                            "video timing stage=release call=$id pts=$heldPts mono_us=${System.nanoTime() / 1000} " +
+                                "audio_pts=${clock[4]} render=$render")
                         decoder!!.releaseOutputBuffer(held, render); held = -1
                         if (render) {
                             rendered++
@@ -82,12 +89,19 @@ internal class CallVideoPlayer(private val id: Long, private val failure: (Strin
                                 } }
                                 lastOutput = info.presentationTimeUs; inflight = (inflight - 1).coerceAtLeast(0)
                                 held = out; heldPts = info.presentationTimeUs; lastProgress = now
+                                if (heldPts % 1_000_000 < 34_000) LogManager.addLog("DEBUG", "debug",
+                                    "video timing stage=decode call=$id pts=$heldPts mono_us=${System.nanoTime() / 1000} " +
+                                        "audio_pts=${clock[4]} audio_valid=$valid inflight=$inflight")
                                 decoded++
                             }
-                        }
+                        } else if (out == MediaCodec.INFO_OUTPUT_FORMAT_CHANGED)
+                            LogManager.addLog("INFO", "call", "video decoder output call=$id format=${decoder!!.outputFormat}")
                     }
                     if (pending == null && held < 0 && inflight < 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 && held < 0) {
@@ -108,8 +122,14 @@ 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 ->
+                                    // Время события, а не доставки callback: Android может группировать уведомления.
+                                    if (running && pts % 1_000_000 < 34_000) LogManager.addLog("DEBUG", "debug",
+                                        "video timing stage=surface call=$id generation=${next.generation} pts=$pts " +
+                                            "mono_us=${at / 1000} callback_us=${System.nanoTime() / 1000}")
+                                }, renderHandler)
                                 decoder!!.start(); format = next; lastProgress = now
-                                LogManager.addLog("INFO", "call", "video decoder started call=$id format=$next")
+                                LogManager.addLog("INFO", "call", "video decoder started call=$id codec=${implementation.name} format=$next")
                             }
                             val index = decoder!!.dequeueInputBuffer(0)
                             if (index >= 0) {
@@ -119,6 +139,8 @@ 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}")
                                 pending = null; inflight++; queued++
                             }
                         }

tools/chatgui-android/app/src/main/java/com/utun/chat/ui/screens/CallVideoPanel.kt

@@ -143,7 +143,13 @@ 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) {}
+            override fun onSurfaceTextureUpdated(texture: SurfaceTexture) {
+                // MediaCodec передаёт исходный PTS в SurfaceTexture; не вычитаем его из локальных часов телефона.
+                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 pts=$pts mono_us=${System.nanoTime() / 1000} generation=${format?.generation} " +
+                        "visible=$isShown alpha=$alpha size=${width}x$height")
+            }
         }
     }
     private fun fit() {