Diagnose Windows call video timing and queue losses

src/call/call_video_playout.c

@@ -43,12 +43,15 @@ static void report(struct call_video_playout *p, int64_t now) {
     DEBUG_DEBUG(DEBUG_CATEGORY_CALL,
         "video playout call=%llu interval_us=%lld shown=%u drop_late=%u drop_schedule=%u drop_order=%u "
         "cadence_us=%lld..%lld gap_pts_us=%lld gap_rx_us=%lld gap_dispatch_us=%lld "
-        "av_us=%lld..%lld dispatch_max_us=%lld data_shift_us=%lld audio_wait=%u clock_wait=%u",
+        "av_us=%lld..%lld dispatch_max_us=%lld data_shift_us=%lld audio_wait=%u clock_wait=%u "
+        "late_av_us=%lld..%lld late_rx_age_us=%lld..%lld",
         (unsigned long long)p->call_id, (long long)(now - p->report_us), p->shown, p->late, p->skipped, p->order,
         (long long)(p->interval_min == INT64_MAX ? 0 : p->interval_min), (long long)p->interval_max,
         (long long)p->gap_pts, (long long)p->gap_received, (long long)p->gap_dispatch,
         (long long)(p->shown ? p->av_min : 0), (long long)(p->shown ? p->av_max : 0),
-        (long long)p->dispatch_max, (long long)p->data_shift, p->audio_wait, p->clock_wait);
+        (long long)p->dispatch_max, (long long)p->data_shift, p->audio_wait, p->clock_wait,
+        (long long)(p->late ? p->late_av_min : 0), (long long)(p->late ? p->late_av_max : 0),
+        (long long)(p->late ? p->late_age_min : 0), (long long)(p->late ? p->late_age_max : 0));
     p->report_us = now; p->shown = p->late = p->skipped = p->order = p->audio_wait = p->clock_wait = 0;
     p->interval_min = p->av_min = INT64_MAX; p->av_max = INT64_MIN;
     p->interval_max = p->dispatch_max = p->data_shift = 0;
@@ -88,7 +91,21 @@ enum call_video_playout_action call_video_playout_poll(struct call_video_playout
     }
     p->last_pts = f->pts_us; p->last_deadline = deadline; p->anchored = 1;
     if (available > planned) p->data_shift += available - planned;
-    if (action == CALL_VIDEO_PLAYOUT_DROP_LATE) p->late++;
+    if (action == CALL_VIDEO_PLAYOUT_DROP_LATE) {
+        int64_t age = now - f->received_us;
+        if (!p->late) {
+            p->late_av_min = p->late_av_max = av; p->late_age_min = p->late_age_max = age;
+            DEBUG_WARN(DEBUG_CATEGORY_CALL, "video late drop call=%llu pts=%lld audio_pts=%lld av_us=%lld limit_us=%d "
+                "rx_age_us=%lld received_us=%lld mono_us=%lld planned_us=%lld deadline_us=%lld",
+                (unsigned long long)p->call_id, (long long)f->pts_us, (long long)audio, (long long)av, VIDEO_LATE_US,
+                (long long)age, (long long)f->received_us, (long long)now, (long long)planned, (long long)deadline);
+        }
+        if (av < p->late_av_min) p->late_av_min = av;
+        if (av > p->late_av_max) p->late_av_max = av;
+        if (age < p->late_age_min) p->late_age_min = age;
+        if (age > p->late_age_max) p->late_age_max = age;
+        p->late++;
+    }
     else if (action == CALL_VIDEO_PLAYOUT_DROP_SCHEDULE) p->skipped++;
     else {
         if (now - deadline > p->dispatch_max) p->dispatch_max = now - deadline;

src/call/call_video_playout.h

@@ -22,6 +22,7 @@ struct call_video_playout {
     int64_t last_pts, last_deadline, deadline_us;
     int64_t report_us, last_show_us, interval_min, interval_max, av_min, av_max, dispatch_max, data_shift;
     int64_t last_show_pts, last_received, gap_pts, gap_received, gap_dispatch;
+    int64_t late_av_min, late_av_max, late_age_min, late_age_max; // A/V и возраст от RX до пропуска за окно сводки.
     unsigned shown, late, skipped, order, audio_wait, clock_wait;
 };
 

src/call/call_video_port.c

@@ -113,6 +113,7 @@ static void process(void *arg) {
     if (opening) port.bound = id;
     pthread_mutex_unlock(&lock);
     int result = 0, sent = 1;
+    unsigned sent_count = 0;
     /* Команды и завершение сессии исполняются одним uasync-потоком: после этой
      * проверки сессия не может завершиться посреди исполнения снимка. */
     struct call_session *session = inst && id ? call_session_find(inst->call, id) : NULL;
@@ -142,7 +143,14 @@ static void process(void *arg) {
         if (id && resume) call_video_resume_receive(inst, id);
         if (id && key) call_video_request_key(inst, id);
         if (id && decoded_pending) call_video_decode_result(inst, id, decoded_generation, decoded_accepted);
-        for (unsigned i = 0; i < tx_count && sent == 1; ++i) sent = call_video_send_frame(inst, &tx[i]);
+        for (; sent_count < tx_count; ++sent_count) {
+            sent = call_video_send_frame(inst, &tx[sent_count]);
+            if (sent != 1) break;
+        }
+        if (sent_count < tx_count)
+            DEBUG_WARN(DEBUG_CATEGORY_CALL, "video port TX frames released call=%llu accepted=%u unsent=%u result=%d "
+                "first_unsent=%llu last=%llu", (unsigned long long)id, sent_count, tx_count - sent_count, sent,
+                (unsigned long long)tx[sent_count].frame_id, (unsigned long long)tx[tx_count - 1].frame_id);
     }
     for (unsigned i = 0; i < tx_count; ++i) u_free((void *)tx[i].data);
     pthread_mutex_lock(&lock);
@@ -245,6 +253,9 @@ int call_video_port_send(const struct call_video_frame *frames, unsigned count)
             result = -1;
         }
     }
+    if (result == 0) DEBUG_WARN(DEBUG_CATEGORY_CALL,
+        "video port TX mailbox busy call=%llu frames=%u first=%llu pending=%u; batch not queued",
+        (unsigned long long)frames[0].call_id, count, (unsigned long long)frames[0].frame_id, port.tx_count);
     pthread_mutex_unlock(&lock); return result;
 }
 int call_video_port_pull(uint64_t id, struct call_video_frame *out) {