Диагностика задержек программного видео на desktop

tools/chatgui/src/call_video_encoder.cpp

@@ -86,14 +86,21 @@ bool CallVideoEncoder::encode(const QImage& image, uint64_t pts, bool forceKey,
             auto replacement = m_prepared.get(); auto& candidate = replacement.encoder;
             QElapsedTimer timer; timer.start();
             bool ready = candidate && candidate->encode(image, pts, true, frames)
-                && frames.size() == 1 && frames.front().key && frames.front().pts == pts
-                && !call_video_check_key(&m_format, reinterpret_cast<const uint8_t*>(frames.front().data.constData()), frames.front().data.size());
+                && frames.size() == 1 && frames.front().key && frames.front().pts == pts;
+            const qint64 encodedUs = timer.nsecsElapsed() / 1000;
+            if (ready) ready = !call_video_check_key(&m_format,
+                reinterpret_cast<const uint8_t*>(frames.front().data.constData()), frames.front().data.size());
+            const qint64 verifiedUs = timer.nsecsElapsed() / 1000;
             if (ready) {
                 m_encoder = std::move(candidate); m_config = next; completion.bitrate = m_pendingBitrate;
+                const qint64 committedUs = timer.nsecsElapsed() / 1000;
                 DEBUG_INFO(DEBUG_CATEGORY_CALL,
-                    "call video bitrate committed generation=%llu request=%llu bitrate=%u pts=%llu background_ms=%lld commit_ms=%lld bytes=%lld",
+                    "call video bitrate committed generation=%llu request=%llu bitrate=%u pts=%llu background_ms=%lld "
+                    "commit_ms=%lld encode_us=%lld verify_us=%lld retire_us=%lld bytes=%lld",
                     (unsigned long long)m_format.generation, (unsigned long long)m_request, completion.bitrate,
-                    (unsigned long long)pts, (long long)replacement.elapsed, (long long)timer.elapsed(), (long long)frames.front().data.size());
+                    (unsigned long long)pts, (long long)replacement.elapsed, (long long)(committedUs / 1000),
+                    (long long)encodedUs, (long long)(verifiedUs - encodedUs), (long long)(committedUs - verifiedUs),
+                    (long long)frames.front().data.size());
             } else {
                 m_error = candidate ? candidate->error() : replacement.error;
                 if (m_error.isEmpty()) m_error = "Replacement encoder did not produce a compatible immediate IDR";

tools/chatgui/src/call_video_engine.cpp

@@ -165,9 +165,9 @@ void CallVideoEngine::transmit() {
     unsigned excluded = 0;
     int64_t lastPts = -1;
     bool forceKey = true;
-    int64_t reportAt = nowUs(), encodeMax = 0;
+    int64_t reportAt = nowUs(), encodeMax = 0, inputAgeMax = 0;
     uint64_t captureBase = 0;
-    unsigned encodedCount = 0, keyCount = 0, sendBusy = 0, paced = 0;
+    unsigned encodedCount = 0, keyCount = 0, sendBusy = 0, paced = 0, expired = 0;
     CallVideoCadence cadence;
     uint64_t wakeSerial = 0;
     auto idle = [this, &wakeSerial] {
@@ -187,13 +187,14 @@ void CallVideoEngine::transmit() {
         }
         int64_t now = nowUs();
         if (now - reportAt >= 1000000) {
-            DEBUG_DEBUG(DEBUG_CATEGORY_CALL,
+            DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG,
                 "video capture flow call=%llu interval_us=%lld captured=%llu encoded=%u keys=%u send_busy=%u paced=%u "
-                "encode_max_us=%lld capture_age_us=%lld pts=%lld clock_correction_us=%lld",
+                "expired=%u encode_max_us=%lld input_age_max_us=%lld capture_age_us=%lld pts=%lld clock_correction_us=%lld",
                 (unsigned long long)m->id, (long long)(now - reportAt), (unsigned long long)(captured - captureBase),
-                encodedCount, keyCount, sendBusy, paced, (long long)encodeMax,
+                encodedCount, keyCount, sendBusy, paced, expired, (long long)encodeMax, (long long)inputAgeMax,
                 (long long)(pts >= 0 ? now - pts : 0), (long long)pts, (long long)clockCorrection);
-            reportAt = now; captureBase = captured; encodedCount = keyCount = sendBusy = paced = 0; encodeMax = 0;
+            reportAt = now; captureBase = captured; encodedCount = keyCount = sendBusy = paced = expired = 0;
+            encodeMax = inputAgeMax = 0;
         }
         if (revision != userRevision) { userRevision = revision; excluded = 0; }
         if (format.generation && state.decoded_generation == format.generation && !state.decoded_accepted
@@ -238,10 +239,11 @@ void CallVideoEngine::transmit() {
         if (!cadence.accept(pts)) { lastPts = pts; ++paced; idle(); continue; }
         if (image.isNull() || nowUs() - pts > CallCameraMaxFrameAgeUs) {
             DEBUG_WARN(DEBUG_CATEGORY_CALL, "video TX skips old capture age_us=%lld", (long long)(nowUs() - pts));
-            lastPts = pts; continue;
+            lastPts = pts; ++expired; continue;
         }
         LiveEncodedFrame output; CallVideoRateCompletion completion;
         int64_t encodeStarted = nowUs();
+        inputAgeMax = std::max(inputAgeMax, encodeStarted - pts);
         bool encoded = encoder.encode(image, pts, forceKey, output, completion); lastPts = pts;
         encodeMax = std::max(encodeMax, nowUs() - encodeStarted);
         if (completion.request) {
@@ -259,6 +261,7 @@ void CallVideoEngine::transmit() {
           if (!m->running || !m->enabled || m->revision != revision || nowUs() - pts > CallCameraMaxFrameAgeUs) {
               DEBUG_WARN(DEBUG_CATEGORY_CALL, "video TX discards obsolete encoded frame revision=%llu/%llu enabled=%d age_us=%lld",
                   (unsigned long long)revision, (unsigned long long)m->revision, m->enabled, (long long)(nowUs() - pts));
+              ++expired;
               forceKey = true; continue;
           }
           forceKey = call_video_port_send(&packet) != 1; }

tools/chatgui/src/live_video_encoder.cpp

@@ -1,5 +1,6 @@
 #include "live_video_encoder.h"
 #include "debug_config.h"
+#include <QElapsedTimer>
 #include <QPainter>
 #include <algorithm>
 #include <cstring>
@@ -18,6 +19,9 @@ struct LiveVideoEncoder::Impl {
     QString error, name;
     LiveVideoConfig config;
     int64_t submittedFrames = 0;
+    QElapsedTimer reportTimer;
+    unsigned inputs = 0, outputs = 0, keys = 0;
+    qint64 prepareMax = 0, submitMax = 0, drainMax = 0, keyMax = 0, deltaMax = 0;
 #ifdef HAVE_FFMPEG
     AVCodecContext* codec = nullptr;
     AVBSFContext* filter = nullptr;
@@ -297,6 +301,9 @@ bool LiveVideoEncoder::encode(const QImage& image, uint64_t pts, bool key, QList
     if (!m->codec || !m->frame || image.isNull() || pts > INT64_MAX) {
         m->error = "Invalid video frame"; DEBUG_ERROR(DEBUG_CATEGORY_VIDEO, "desktop encode invalid frame/state"); return false;
     }
+    QElapsedTimer timer; timer.start();
+    if (!m->reportTimer.isValid()) m->reportTimer.start();
+    const auto outputBase = output.size();
     QImage canvas(m->config.width, m->config.height, QImage::Format_RGB32); canvas.fill(Qt::black);
     QSize fitted = image.size().scaled(canvas.size(), Qt::KeepAspectRatio);
     { QPainter painter(&canvas); painter.drawImage(QRect(QPoint((canvas.width() - fitted.width()) / 2,
@@ -325,7 +332,9 @@ bool LiveVideoEncoder::encode(const QImage& image, uint64_t pts, bool key, QList
         if (result >= 0) result = av_hwframe_transfer_data(hardware, m->frame, 0);
         if (result >= 0) result = av_frame_copy_props(hardware, m->frame);
     }
+    const qint64 preparedUs = timer.nsecsElapsed() / 1000;
     if (result >= 0) result = avcodec_send_frame(m->codec, hardware ? hardware : m->frame);
+    const qint64 submittedUs = timer.nsecsElapsed() / 1000;
     if (result >= 0) m->submittedFrames++;
     av_frame_free(&hardware);
     AVPacket* packet = av_packet_alloc();
@@ -355,6 +364,27 @@ bool LiveVideoEncoder::encode(const QImage& image, uint64_t pts, bool key, QList
     }
     av_packet_free(&packet);
     if (result == AVERROR(EAGAIN) || result == AVERROR_EOF) {
+        // Сводка по этапам отличает конвертацию, синхронный encoder и получение/упаковку пакета.
+        const qint64 totalUs = timer.nsecsElapsed() / 1000;
+        ++m->inputs; m->outputs += output.size() - outputBase;
+        bool producedKey = false;
+        for (auto i = outputBase; i < output.size(); ++i) if (output[i].key) { ++m->keys; producedKey = true; }
+        m->prepareMax = std::max(m->prepareMax, preparedUs);
+        m->submitMax = std::max(m->submitMax, submittedUs - preparedUs);
+        m->drainMax = std::max(m->drainMax, totalUs - submittedUs);
+        auto& frameMax = producedKey ? m->keyMax : m->deltaMax;
+        frameMax = std::max(frameMax, totalUs);
+        if (m->reportTimer.elapsed() >= 1000) {
+            DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG,
+                "video encoder flow name=%s size=%dx%d bitrate=%d interval_us=%lld inputs=%u outputs=%u keys=%u "
+                "prepare_max_us=%lld submit_max_us=%lld drain_max_us=%lld key_max_us=%lld delta_max_us=%lld pts=%llu",
+                qPrintable(m->name), m->config.width, m->config.height, m->config.bitrate,
+                (long long)(m->reportTimer.nsecsElapsed() / 1000), m->inputs, m->outputs, m->keys,
+                (long long)m->prepareMax, (long long)m->submitMax, (long long)m->drainMax,
+                (long long)m->keyMax, (long long)m->deltaMax, (unsigned long long)pts);
+            m->reportTimer.restart(); m->inputs = m->outputs = m->keys = 0;
+            m->prepareMax = m->submitMax = m->drainMax = m->keyMax = m->deltaMax = 0;
+        }
         if (key && output.isEmpty()) DEBUG_DEBUG(DEBUG_CATEGORY_VIDEO, "desktop requested KEY buffered name=%s PTS=%llu",
             qPrintable(m->name), (unsigned long long)pts);
         return true;