Report decoder stage timings and detect real output stalls independently of playback waits

tools/chatgui/src/call_video_decoder.cpp

@@ -33,6 +33,8 @@ struct CallVideoDecoder::Impl {
     QString error;
     unsigned pipeline = 0;
     bool gpu = false, eos = false, outputSeen = false;
+    int64_t reportAt = 0, submitMax = 0, decodeMax = 0, transferMax = 0, convertMax = 0;
+    unsigned submitted = 0, received = 0;
 #ifdef HAVE_FFMPEG
     AVCodecContext* codec = nullptr;
     AVPixelFormat pixel = AV_PIX_FMT_NONE;
@@ -70,6 +72,7 @@ struct CallVideoDecoder::Impl {
         }
         int result = avcodec_open2(codec, implementation, nullptr);
         if (result < 0) { failed("open", result); return false; }
+        error.clear();
         DEBUG_INFO(DEBUG_CATEGORY_CALL, "video decoder opened codec=%u name=%s backend=%s threads=%d thread_type=%d level=%u generation=%llu",
             f.codec, implementation->name, gpu ? av_hwdevice_get_type_name(DeviceType) : "cpu", codec->thread_count,
             codec->active_thread_type, f.level, (unsigned long long)f.generation); return true;
@@ -128,6 +131,7 @@ int CallVideoDecoder::submit(const call_video_frame& f) {
     AVPacket* packet = av_packet_alloc();
     if (!packet) return m->failed("packet allocation", AVERROR(ENOMEM));
     int result = av_new_packet(packet, size);
+    const int64_t started = call_video_playout_now_us();
     if (result >= 0) {
         memcpy(packet->data, data, size); packet->pts = packet->dts = f.pts_us;
         result = avcodec_send_packet(m->codec, packet);
@@ -135,6 +139,7 @@ int CallVideoDecoder::submit(const call_video_frame& f) {
     av_packet_free(&packet);
     if (result == AVERROR(EAGAIN)) return 0;
     if (result < 0) return m->failed("input", result);
+    m->submitMax = std::max(m->submitMax, call_video_playout_now_us() - started); ++m->submitted;
     m->pending.push_back(f); m->pending.back().data = nullptr;
     return 1;
 #else
@@ -147,7 +152,9 @@ int CallVideoDecoder::receive(call_video_frame& f, QImage& image) {
     if (!m->codec) return 0;
     AVFrame* decoded = av_frame_alloc(); AVFrame* copied = nullptr;
     if (!decoded) return m->failed("frame allocation", AVERROR(ENOMEM));
+    const int64_t started = call_video_playout_now_us();
     int result = avcodec_receive_frame(m->codec, decoded);
+    const int64_t decodedAt = call_video_playout_now_us();
     if (result == AVERROR(EAGAIN) || result == AVERROR_EOF) {
         av_frame_free(&decoded);
         if (result == AVERROR_EOF && !m->pending.empty()) return m->failed("EOS lost accepted frames", AVERROR_INVALIDDATA);
@@ -169,6 +176,7 @@ int CallVideoDecoder::receive(call_video_frame& f, QImage& image) {
         result = copied ? av_hwframe_transfer_data(copied, decoded, 0) : AVERROR(ENOMEM);
         pixels = copied;
     }
+    const int64_t transferredAt = call_video_playout_now_us();
     if (result >= 0 && pixels->format != AV_PIX_FMT_YUV420P && pixels->format != AV_PIX_FMT_NV12) result = AVERROR_INVALIDDATA;
     if (result >= 0) {
         QImage output = video_frame_image(pixels->width, pixels->height);
@@ -184,11 +192,25 @@ int CallVideoDecoder::receive(call_video_frame& f, QImage& image) {
     }
     av_frame_free(&copied); av_frame_free(&decoded);
     if (result < 0) return m->failed("output PTS/profile/geometry/transfer", result);
+    const int64_t now = call_video_playout_now_us();
+    m->decodeMax = std::max(m->decodeMax, decodedAt - started);
+    m->transferMax = std::max(m->transferMax, transferredAt - decodedAt);
+    m->convertMax = std::max(m->convertMax, now - transferredAt); ++m->received;
     if (!m->outputSeen) {
         if (m->backend == Backend::HardwareOnly) m->pipeline = static_cast<unsigned>(m->pending.size() - 1);
         m->outputSeen = true;
     }
-    m->pending.pop_front(); return 1;
+    m->pending.pop_front();
+    if (!m->reportAt) m->reportAt = now;
+    if (now - m->reportAt >= 1000000) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "video decoder pipeline codec=%u backend=%s threads=%d thread_type=%d interval_us=%lld "
+            "submitted=%u received=%u pending=%zu pipeline=%u submit_max_us=%lld decode_max_us=%lld transfer_max_us=%lld convert_max_us=%lld",
+            m->format.codec, m->gpu ? av_hwdevice_get_type_name(DeviceType) : "cpu", m->codec->thread_count,
+            m->codec->active_thread_type, (long long)(now - m->reportAt), m->submitted, m->received, m->pending.size(), m->pipeline,
+            (long long)m->submitMax, (long long)m->decodeMax, (long long)m->transferMax, (long long)m->convertMax);
+        m->reportAt = now; m->submitMax = m->decodeMax = m->transferMax = m->convertMax = 0; m->submitted = m->received = 0;
+    }
+    return 1;
 #else
     Q_UNUSED(f); Q_UNUSED(image); return -1;
 #endif

tools/chatgui/src/call_video_engine.cpp

@@ -386,6 +386,7 @@ void CallVideoEngine::receive() {
     uint64_t reportedGeneration = 0, rejectedGeneration = 0;
     call_video_frame input{};
     bool wakeBound = false, waitingKey = false;
+    int64_t decoderProgressAt = nowUs();
     while (m->running) {
         const uint64_t ticket = m->rxWake.ticket();
         if (requestedWake) wakeLateMax = std::max(wakeLateMax, nowUs() - requestedWake);
@@ -415,14 +416,21 @@ void CallVideoEngine::receive() {
             call_video_frame packet{}; QImage image;
             const int64_t started = nowUs(); int result = decoder.receive(packet, image);
             decodeMax = std::max(decodeMax, nowUs() - started);
+            if (!result && !playout.awaiting && pictures.empty() && decoder.pendingFrames() > decoder.pipelineFrames()
+                && nowUs() - decoderProgressAt > 2000000) {
+                DEBUG_ERROR(DEBUG_CATEGORY_CALL, "video decoder stalled call=%llu pending=%u pipeline=%u progress_age_us=%lld",
+                    (unsigned long long)m->id, decoder.pendingFrames(), decoder.pipelineFrames(), (long long)(nowUs() - decoderProgressAt));
+                result = -1;
+            }
             if (result < 0) {
                 DEBUG_ERROR(DEBUG_CATEGORY_CALL, "video decoder recovery call=%llu lost_inputs=%u retained_ready=%zu awaiting=%d error=%s",
                     (unsigned long long)m->id, decoder.pendingFrames(), pictures.size(), playout.awaiting, qPrintable(decoder.error()));
-                m->report(decoder.error());
+                m->report(decoder.error().isEmpty() ? tr("Video decoder stopped producing frames") : decoder.error());
                 if (decoder.hardware()) decoder.useSoftware(); else decoder.close();
                 waitingKey = true; call_video_port_request_key(m->id); break;
             }
             if (!result) break;
+            decoderProgressAt = nowUs();
             ++decoded; worked = true; rxAgeMax = std::max(rxAgeMax, nowUs() - packet.received_us);
             pictures.push_back({{packet.pts_us, packet.received_us, 1000000u / packet.format.fps}, image});
             if (reportedGeneration != packet.format.generation) {
@@ -440,7 +448,10 @@ void CallVideoEngine::receive() {
                 decodeMax = std::max(decodeMax, nowUs() - started);
                 if (result) {
                     worked = true;
-                    if (result > 0) { ++submitted; waitingKey = false; }
+                    if (result > 0) {
+                        ++submitted; waitingKey = false;
+                        if (decoder.pendingFrames() == 1) decoderProgressAt = nowUs();
+                    }
                     else {
                         m->report(decoder.error());
                         if (decoder.hardware()) {