Trace sampled video frames through desktop encoding and transport

src/call/call_video_transport.c

@@ -211,7 +211,14 @@ static void flush(struct call_video_transport *v) {
         if (call_video_fragment_encode(f, wire, sizeof(wire), &length)
             || etcp_router_conn_send(conn, wire, length, 0)) { discard_tx(v, "router_send"); return; }
         f->offset += f->length;
-        if (f->offset == f->size) pop_tx(v);
+        if (f->offset == f->size) {
+            if (f->pts_us % 1000000 < 34000)
+                DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG,
+                    "video timing stage=send call=%llu frame=%llu pts=%lld boot_us=%llu bytes=%u queue_age_us=%llu",
+                    (unsigned long long)f->call_id, (unsigned long long)f->frame_id, (long long)f->pts_us,
+                    (unsigned long long)get_time_us(), f->size, (unsigned long long)((get_time_tb() - head->started_tb) * 100));
+            pop_tx(v);
+        }
     }
 }
 static void tick(void *arg) {
@@ -466,7 +473,13 @@ static void receive(struct ETCP_CONN *conn, struct ll_entry *entry) {
         if (!v->have_peer || !call_video_format_supported(&v->peer, &v->local, &f.format)) goto invalid;
         struct call_video_frame complete;
         int result = call_video_receiver_push(v->receiver, &f, get_time_us(), &complete);
-        if (result == 1) { v->received_generation = complete.format.generation; v->ops.frame(v->arg, &complete); }
+        if (result == 1) {
+            if (complete.pts_us % 1000000 < 34000)
+                DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "video timing stage=receive call=%llu frame=%llu pts=%lld boot_us=%llu bytes=%u",
+                    (unsigned long long)id, (unsigned long long)complete.frame_id, (long long)complete.pts_us,
+                    (unsigned long long)get_time_us(), complete.size);
+            v->received_generation = complete.format.generation; v->ops.frame(v->arg, &complete);
+        }
         else if (result < 0 || (!(f.flags & CALL_VIDEO_KEY) && call_video_receiver_needs_key(v->receiver)))
             call_video_request_key(conn->instance, id);
     }

tools/chatgui/src/call_video_engine.cpp

@@ -264,6 +264,7 @@ void CallVideoEngine::transmit() {
         }
 #ifdef HAVE_STREAM_CAPTURE
         if (!cadence.accept(pts)) { lastPts = pts; ++paced; idle(); continue; }
+        const int64_t convertStarted = nowUs();
         QImage image = raw.toImage();
         if (image.isNull()) { DEBUG_WARN(DEBUG_CATEGORY_CALL, "camera frame conversion failed"); lastPts = pts; continue; }
         LiveEncodedFrame output; CallVideoRateCompletion completion;
@@ -283,6 +284,12 @@ void CallVideoEngine::transmit() {
         packet.size = packet.length = output.data.size(); packet.data = reinterpret_cast<const uint8_t*>(output.data.constData());
         packet.flags = output.key ? CALL_VIDEO_KEY : 0;
         forceKey = call_video_port_send(&packet) != 1;
+        // Одинаковое окно исходного PTS на всех этапах: примерно один кадр в секунду, без трассы каждого кадра.
+        if (pts % 1000000 < 34000)
+            DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG,
+                "video timing stage=encode call=%llu frame=%llu pts=%lld mono_us=%lld select_us=%lld convert_us=%lld encode_us=%lld accepted=%d",
+                (unsigned long long)m->id, (unsigned long long)frameId, (long long)pts, (long long)nowUs(),
+                (long long)convertStarted, (long long)(encodeStarted - convertStarted), (long long)(nowUs() - encodeStarted), !forceKey);
         if (forceKey) ++sendBusy;
 #else
         idle();