Trace GUI event loop stalls separately from video painting and dispatch

tools/chatgui/src/call_video_engine.cpp

@@ -39,6 +39,8 @@ struct CallVideoEngine::Impl {
     int64_t publicationQueuedAt = 0;
     int64_t paintWaitMax = 0; // Только под lock: время до подтверждения рисования.
     int64_t uiReportAt = 0, uiLastAt = 0, uiWaitMax = 0, uiGapMax = 0; // Только GUI-поток.
+    int64_t uiTickAt = 0, uiTickReportAt = 0, uiTickGapMax = 0, uiImageSlotMax = 0;
+    unsigned uiTicks = 0;
     unsigned uiPublished = 0;
     int64_t previewReportAt = 0, previewMaxUs = 0;
     unsigned previewFrames = 0;
@@ -56,6 +58,18 @@ CallVideoEngine::CallVideoEngine(QObject* parent) : QObject(parent), m(std::make
     m_timer.setInterval(20);
     m_timer.setTimerType(Qt::PreciseTimer);
     connect(&m_timer, &QTimer::timeout, this, [this] {
+        const int64_t now = nowUs(), gap = m->uiTickAt ? now - m->uiTickAt : 0;
+        if (gap > 50000 && m->uiTickGapMax <= 50000)
+            DEBUG_WARN(DEBUG_CATEGORY_CALL, "video GUI loop delayed call=%llu tick_gap_us=%lld expected_us=20000 mono_us=%lld",
+                (unsigned long long)m->id, (long long)gap, (long long)now);
+        m->uiTickAt = now; m->uiTickGapMax = std::max(m->uiTickGapMax, gap); ++m->uiTicks;
+        if (!m->uiTickReportAt) m->uiTickReportAt = now;
+        if (now - m->uiTickReportAt >= 1000000) {
+            DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "video GUI loop call=%llu interval_us=%lld ticks=%u tick_gap_max_us=%lld mono_us=%lld",
+                (unsigned long long)m->id, (long long)(now - m->uiTickReportAt), m->uiTicks,
+                (long long)m->uiTickGapMax, (long long)now);
+            m->uiTickReportAt = now; m->uiTicks = 0; m->uiTickGapMax = 0;
+        }
         QString status; bool report = false;
         { std::lock_guard<std::mutex> guard(m->lock);
           if (m->statusDirty) { status = m->status; m->statusDirty = false; report = true; } }
@@ -114,6 +128,11 @@ void CallVideoEngine::publishImage(const QImage& image, int64_t pts) {
         if (m->uiLastAt) m->uiGapMax = std::max(m->uiGapMax, now - m->uiLastAt);
         m->uiLastAt = now;
         emit imageChanged(image, serial);
+        const int64_t slotUs = nowUs() - now;
+        if (slotUs > 20000 && m->uiImageSlotMax <= 20000)
+            DEBUG_WARN(DEBUG_CATEGORY_CALL, "video GUI image slot slow call=%llu serial=%llu work_us=%lld mono_us=%lld",
+                (unsigned long long)m->id, (unsigned long long)serial, (long long)slotUs, (long long)now);
+        m->uiImageSlotMax = std::max(m->uiImageSlotMax, slotUs);
         bool driven;
         { std::lock_guard<std::mutex> guard(m->lock); driven = m->presentationDriven; }
         if (!driven || image.isNull()) imagePresented(serial);
@@ -122,10 +141,11 @@ void CallVideoEngine::publishImage(const QImage& image, int64_t pts) {
             int64_t paintWait;
             { std::lock_guard<std::mutex> guard(m->lock); paintWait = m->paintWaitMax; m->paintWaitMax = 0; }
             DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "video GUI delivery call=%llu interval_us=%lld published=%u "
-                "notification_wait_max_us=%lld delivery_gap_max_us=%lld paint_wait_max_us=%lld mono_us=%lld",
+                "notification_wait_max_us=%lld delivery_gap_max_us=%lld paint_wait_max_us=%lld image_slot_max_us=%lld mono_us=%lld",
                 (unsigned long long)m->id, (long long)(now - m->uiReportAt), m->uiPublished,
-                (long long)m->uiWaitMax, (long long)m->uiGapMax, (long long)paintWait, (long long)now);
+                (long long)m->uiWaitMax, (long long)m->uiGapMax, (long long)paintWait, (long long)m->uiImageSlotMax, (long long)now);
             m->uiReportAt = now; m->uiPublished = 0; m->uiWaitMax = m->uiGapMax = 0;
+            m->uiImageSlotMax = 0;
         }
         if (!image.isNull() && pts >= 0 && pts % 1000000 < 34000)
             DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "video timing stage=publish call=%llu pts=%lld mono_us=%lld ui_wait_us=%lld",
@@ -136,6 +156,7 @@ void CallVideoEngine::start(quint64 id) {
     if (m->running && m->id == id) return;
     stop(); m->id = id; m->running = true; m_timer.start();
     m->uiReportAt = m->uiLastAt = m->uiWaitMax = m->uiGapMax = 0; m->uiPublished = 0;
+    m->uiTickAt = m->uiTickReportAt = m->uiTickGapMax = m->uiImageSlotMax = 0; m->uiTicks = 0;
     try { m->tx = std::thread(&CallVideoEngine::transmit, this); m->rx = std::thread(&CallVideoEngine::receive, this); }
     catch (const std::exception& error) { DEBUG_ERROR(DEBUG_CATEGORY_CALL, "video worker start: %s", error.what()); stop(); emit statusChanged(error.what()); }
 }

tools/chatgui/src/callwindow.cpp

@@ -4,6 +4,7 @@
 #include "call_audio_engine.h"
 #include "call_video_engine.h"
 #include "../../../src/call/call_video_port.h"
+#include "../../../src/call/call_video_playout.h"
 #include "sound_manager.h"
 
 #include <QVBoxLayout>
@@ -46,7 +47,11 @@ public:
     QImage remote, local;
     CallVideoEngine* engine = nullptr;
     quint64 serial = 0;
+    quint64 callId = 0;
+    int64_t requestedAt = 0; // GUI-получение кадра -> начало paintEvent, отдельно от самой работы painter.
 protected:
+    void moveEvent(QMoveEvent* event) override { ++m_moves; QWidget::moveEvent(event); }
+    void resizeEvent(QResizeEvent* event) override { ++m_resizes; QWidget::resizeEvent(event); }
     void hideEvent(QHideEvent* event) override { presented(); QWidget::hideEvent(event); }
     void changeEvent(QEvent* event) override {
         QWidget::changeEvent(event);
@@ -66,17 +71,47 @@ protected:
         QWidget::mouseDoubleClickEvent(event);
     }
     void paintEvent(QPaintEvent*) override {
+        const int64_t started = call_video_playout_now_us(), requestWait = serial && requestedAt ? started - requestedAt : 0;
+        const bool selected = serial != 0;
         QPainter painter(this); painter.fillRect(rect(), Qt::black); painter.setRenderHint(QPainter::SmoothPixmapTransform);
         if (remote.isNull()) return;
         QSize fitted = remote.size().scaled(size(), Qt::KeepAspectRatio);
         QRect videoRect(QPoint((width() - fitted.width()) / 2, (height() - fitted.height()) / 2), fitted);
+        const int64_t prepared = call_video_playout_now_us();
         painter.drawImage(videoRect, remote);
+        const int64_t drawn = call_video_playout_now_us();
         if (!local.isNull()) {
             QSize preview = local.size().scaled(qMin(200, fitted.width() / 4), qMin(150, fitted.height() / 4), Qt::KeepAspectRatio);
             QRect target(QPoint(videoRect.right() - preview.width() - 12, videoRect.top() + 12), preview);
             painter.setPen(QPen(Qt::white, 2)); painter.drawRect(target.adjusted(-1, -1, 1, 1)); painter.drawImage(target, local);
         }
-        painter.end(); presented();
+        const int64_t overlay = call_video_playout_now_us();
+        painter.end();
+        const int64_t finished = call_video_playout_now_us();
+        presented();
+        ++m_paints; if (selected) ++m_selectedPaints;
+        m_requestMax = std::max(m_requestMax, requestWait); m_paintMax = std::max(m_paintMax, finished - started);
+        m_prepareMax = std::max(m_prepareMax, prepared - started); m_drawMax = std::max(m_drawMax, drawn - prepared);
+        m_overlayMax = std::max(m_overlayMax, overlay - drawn); m_finishMax = std::max(m_finishMax, finished - overlay);
+        if (!m_slowReported && (requestWait > 50000 || finished - started > 20000)) {
+            DEBUG_WARN(DEBUG_CATEGORY_CALL, "video GUI paint delayed call=%llu request_wait_us=%lld paint_us=%lld "
+                "prepare_us=%lld draw_us=%lld overlay_us=%lld finish_us=%lld window=%dx%d image=%dx%d dpr_x1000=%d mono_us=%lld",
+                (unsigned long long)callId, (long long)requestWait, (long long)(finished - started),
+                (long long)(prepared - started), (long long)(drawn - prepared), (long long)(overlay - drawn),
+                (long long)(finished - overlay), width(), height(), remote.width(), remote.height(),
+                int(devicePixelRatioF() * 1000), (long long)finished);
+            m_slowReported = true;
+        }
+        if (!m_reportAt) m_reportAt = started;
+        if (finished - m_reportAt >= 1000000) {
+            DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "video GUI paint call=%llu interval_us=%lld paints=%u selected=%u moves=%u resizes=%u "
+                "request_wait_max_us=%lld paint_max_us=%lld prepare_max_us=%lld draw_max_us=%lld overlay_max_us=%lld finish_max_us=%lld",
+                (unsigned long long)callId, (long long)(finished - m_reportAt), m_paints, m_selectedPaints, m_moves, m_resizes,
+                (long long)m_requestMax, (long long)m_paintMax, (long long)m_prepareMax, (long long)m_drawMax,
+                (long long)m_overlayMax, (long long)m_finishMax);
+            m_reportAt = finished; m_paints = m_selectedPaints = m_moves = m_resizes = 0;
+            m_requestMax = m_paintMax = m_prepareMax = m_drawMax = m_overlayMax = m_finishMax = 0; m_slowReported = false;
+        }
     }
 private:
     void presented() {
@@ -87,6 +122,9 @@ private:
         else { m_geometry = saveGeometry(); showFullScreen(); }
     }
     QByteArray m_geometry;
+    int64_t m_reportAt = 0, m_requestMax = 0, m_paintMax = 0, m_prepareMax = 0, m_drawMax = 0, m_overlayMax = 0, m_finishMax = 0;
+    unsigned m_paints = 0, m_selectedPaints = 0, m_moves = 0, m_resizes = 0;
+    bool m_slowReported = false;
 };
 
 static QColor colorForName(const QString& name) {
@@ -331,7 +369,8 @@ CallWindow::CallWindow(QWidget* parent)
     });
     connect(m_video, &CallVideoEngine::imageChanged, this, [this](const QImage& image, quint64 serial) {
         bool changed = m_remoteImage.isNull() != image.isNull(); m_remoteImage = image;
-        m_videoWindow->remote = image; m_videoWindow->serial = serial; m_videoWindow->update();
+        m_videoWindow->remote = image; m_videoWindow->serial = serial; m_videoWindow->callId = m_videoCall;
+        m_videoWindow->requestedAt = call_video_playout_now_us(); m_videoWindow->update();
         if (changed) updateVideoPresentation();
         // Скрытое окно продолжает принимать поток, не ждёт невозможного paintEvent.
         if (!m_videoWindow->isVisible() || m_videoWindow->isMinimized()) m_video->imagePresented(serial);