From 2a08fd8acd0e627058547b1f2760e6bedd6cd471 Mon Sep 17 00:00:00 2001 From: evgeny Date: Mon, 19 Oct 2026 19:19:27 +0200 Subject: [PATCH] Report decoder stage timings and detect real output stalls independently of playback waits --- tools/chatgui/src/call_video_decoder.cpp | 24 +++++++++++++++++++++++- tools/chatgui/src/call_video_engine.cpp | 15 +++++++++++++-- 2 files changed, 36 insertions(+), 3 deletions(-) diff --git a/tools/chatgui/src/call_video_decoder.cpp b/tools/chatgui/src/call_video_decoder.cpp index 6a488707..06b6f645 100644 --- a/tools/chatgui/src/call_video_decoder.cpp +++ b/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(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 diff --git a/tools/chatgui/src/call_video_engine.cpp b/tools/chatgui/src/call_video_engine.cpp index 377b6b46..45d93f88 100644 --- a/tools/chatgui/src/call_video_engine.cpp +++ b/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()) {