Trace first video frame and verify capability upgrades preserve RX

tests/test_call_video_port.c

@@ -77,6 +77,15 @@ int main(void) {
     DEBUG_INFO(DEBUG_CATEGORY_CALL, "PASS video port: all 8 frames preserved across partial send and repeated busy; no KEY or spin");
     for (unsigned i = 0; i < 8; ++i) { assert(callbacks->receive_ready(callback_arg, 16)); callbacks->frame(callback_arg, &frames[i]); }
     assert(woken == 8 && !call_video_port_status(7, &status) && status.rx_frames == 8);
+    // RX уже работает: добавление собственных encoder CAPS не сбрасывает очередь и callbacks.
+    caps.decode[0] = (struct call_video_limit){1280, 720, 60, 1280 * 720 * 60, 4000000, 3, 42};
+    callbacks->capabilities(callback_arg, &caps);
+    caps.encode[0] = caps.decode[0];
+    assert(!call_video_port_open(7, &caps)); uasync_poll(ua, 0);
+    assert(!call_video_port_status(7, &status) && status.rx_frames == 8 && status.have_peer && status.can_encode);
+    assert(status.peer.decode[0].fps == 60 && woken == 8 && port.rx_wake == wake && port.rx_wake_arg == &woken);
+    assert(call_video_port_received(7) == 8 && port.local.encode[0].fps == 60);
+    DEBUG_INFO(DEBUG_CATEGORY_CALL, "PASS video port: same-call CAPS upgrade preserves RX frames, wake, peer and received count");
     pthread_mutex_lock(&lock); // Reader планировщика не должен захватывать mutex порта.
     assert(call_video_port_received(7) == 8 && !call_video_port_received(8));
     pthread_mutex_unlock(&lock);

tools/chatgui-android/app/src/debug/java/com/utun/chat/data/CallVideoHevcProbe.kt

@@ -25,13 +25,30 @@ object CallVideoHevcProbe {
     }
 
     @JvmStatic fun main(args: Array<String>) {
-        require(args.size in 1..2 && (args.size == 1 || args[1] in listOf("parameters", "call", "receive"))) {
-            "Expected output directory [parameters|call|receive]"
+        require(args.size in 1..2 && (args.size == 1 || args[1] in listOf("parameters", "call", "receive", "capabilities"))) {
+            "Expected output directory [parameters|call|receive|capabilities]"
         }
         check(Build.VERSION.SDK_INT >= 29) { "Hardware codec enumeration requires API 29" }
         val directory = File(args[0]); check(directory.isDirectory || directory.mkdirs())
         val journal = File(directory, "results.log")
         fun report(message: String) { Log.i(TAG, message); journal.appendText("$message\n") }
+        if (args.getOrNull(1) == "capabilities") {
+            // Отмена до/после прогрева не должна публиковать или очищать проверенные режимы.
+            check(CallVideoCodec.probeDecoders { false }.isEmpty() && CallVideoCodec.probe { false }.isEmpty())
+            val started = System.nanoTime()
+            val decoders = CallVideoCodec.probeDecoders(); val receiveAt = System.nanoTime()
+            check(decoders.isNotEmpty()) { "No verified video decoders" }
+            report("capabilities cold receiveMs=${(receiveAt - started) / 1_000_000} modes=${decoders.values.sumOf { it.modes.size }}")
+            val encoders = CallVideoCodec.probe(); val duplexAt = System.nanoTime()
+            check(encoders.isNotEmpty()) { "No verified video encoders" }
+            report("capabilities cold encodeMs=${(duplexAt - receiveAt) / 1_000_000} totalMs=${(duplexAt - started) / 1_000_000} " +
+                "modes=${encoders.values.sumOf { it.modes.size }}")
+            check(CallVideoCodec.probeDecoders { false }.isEmpty() && CallVideoCodec.probe { false }.isEmpty())
+            val warmAt = System.nanoTime()
+            repeat(3) { check(CallVideoCodec.probeDecoders() == decoders && CallVideoCodec.probe() == encoders) }
+            report("capabilities PASSED repeatCalls=3 totalUs=${(System.nanoTime() - warmAt) / 1000} verifiedModesUnchanged=true")
+            return
+        }
         val encoder = MediaCodecList(MediaCodecList.REGULAR_CODECS).codecInfos.first {
             it.isEncoder && it.isHardwareAccelerated && "video/hevc" in it.supportedTypes
         }

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

@@ -9,6 +9,7 @@ import java.util.ArrayDeque
 
 /** Один RX worker, общий абсолютный таймер показа. Новое поколение ждёт drain старого. */
 internal class CallVideoPlayer(private val id: Long, private val failure: (String) -> Unit) {
+    private val createdAt = System.nanoTime()
     @Volatile private var running = true
     private data class Output(val surface: Surface?, val release: () -> Unit, val detach: Surface? = null)
     private val outputs = ConcurrentLinkedQueue<Output>()
@@ -49,6 +50,7 @@ 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
         var acknowledged = 0; var ackMaxUs = 0L
+        var firstInput = true; var firstDecoded = true; var firstPresented = true
         val clock = LongArray(8); val info = MediaCodec.BufferInfo()
         fun close() {
             try { decoder?.stop() } catch (e: Exception) { LogManager.addLog("WARN", "call", "video decoder stop: ${e.message}") }
@@ -67,13 +69,19 @@ internal class CallVideoPlayer(private val id: Long, private val failure: (Strin
                         close(); output?.release?.invoke(); output = next; surface = next.surface
                         CallVideoNative.playoutReset(playout)
                         pending = null; displayed.value = null; CallVideoNative.requestKey(id)
-                        LogManager.addLog("INFO", "call", "video output attached=${surface != null} call=$id")
+                        LogManager.addLog("INFO", "call", "video output attached=${surface != null} call=$id elapsedMs=${(System.nanoTime() - createdAt) / 1_000_000}")
                     }
                     while (true) {
                         val consumed = presentations.poll() ?: break
                         if (consumed.surface === surface && consumed.pts == awaitingPts) {
                             acknowledged++; ackMaxUs = maxOf(ackMaxUs, (consumed.at * 1000 - lastRendered) / 1000)
                             CallVideoNative.playoutPresented(playout, consumed.pts, consumed.at)
+                            if (firstPresented) {
+                                firstPresented = false
+                                LogManager.addLog("INFO", "call", "video startup call=$id stage=first_presented " +
+                                    "elapsedMs=${(consumed.at * 1000 - createdAt) / 1_000_000} pts=${consumed.pts} " +
+                                    "surfaceWaitUs=${(consumed.at * 1000 - lastRendered) / 1000}")
+                            }
                             awaitingPts = -1; awaiting = null; worked = true
                         }
                     }
@@ -92,6 +100,11 @@ 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 (firstDecoded) {
+                                    firstDecoded = false
+                                    LogManager.addLog("INFO", "call", "video startup call=$id stage=first_decoded " +
+                                        "elapsedMs=${(System.nanoTime() - createdAt) / 1_000_000} pts=$lastOutput format=$format")
+                                }
                                 decoded++
                             }
                         } else if (out == MediaCodec.INFO_OUTPUT_FORMAT_CHANGED) {
@@ -113,7 +126,8 @@ internal class CallVideoPlayer(private val id: Long, private val failure: (Strin
                         if (render) {
                             awaitingPts = first.timing.pts
                             rendered++
-                            if (displayed.value != format) LogManager.addLog("INFO", "call", "video visible call=$id format=$format")
+                            if (displayed.value != format) LogManager.addLog("INFO", "call", "video visible call=$id format=$format " +
+                                "elapsedMs=${(now - createdAt) / 1_000_000} pts=${first.timing.pts}")
                             displayed.value = format; lastRendered = now
                         } else late++
                         lastProgress = now
@@ -126,7 +140,16 @@ internal class CallVideoPlayer(private val id: Long, private val failure: (Strin
                     // Ожидание срока output не останавливает подачу input; очередь остаётся ограниченной.
                     val decodedSpace = pictures.size + (if (awaitingPts >= 0) 1 else 0) < 3
                     if (pending == null && inputs.size < 8 && decodedSpace) {
-                        pending = CallVideoNative.pull(id, meta); if (pending != null) pulled++
+                        pending = CallVideoNative.pull(id, meta)
+                        if (pending != null) {
+                            pulled++
+                            if (firstInput) {
+                                firstInput = false
+                                LogManager.addLog("INFO", "call", "video startup call=$id stage=first_received " +
+                                    "elapsedMs=${(System.nanoTime() - createdAt) / 1_000_000} generation=${meta[0]} pts=${meta[10]} " +
+                                    "key=${meta[11] != 0L} surfaceReady=${surface?.isValid == true}")
+                            }
+                        }
                     }
                     val data = pending
                     if (data != null && surface?.isValid == true && decodedSpace) {