diff --git a/tools/chatgui/src/mainwindow.cpp b/tools/chatgui/src/mainwindow.cpp index fbd39967..2b1b8a8d 100644 --- a/tools/chatgui/src/mainwindow.cpp +++ b/tools/chatgui/src/mainwindow.cpp @@ -47,6 +47,7 @@ extern "C" { #include "../transport/gui_bridge.h" #include #include +#include #include #include #include @@ -664,6 +665,7 @@ void MainWindow::setupBridgeCallbacks() { /* Один publisher обслуживает шапку и свою плитку; окно управления не владеет сеткой и её readers. */ void MainWindow::showStreamPublisher(quint64 group, StreamGridWindow* returnTo) { + QElapsedTimer elapsed; elapsed.start(); if (!m_streamPublisher) { m_streamPublisher = new StreamPublishEngine(this); connect(m_streamPublisher, &StreamPublishEngine::stateChanged, this, [this](const QString& state) { @@ -674,9 +676,12 @@ void MainWindow::showStreamPublisher(quint64 group, StreamGridWindow* returnTo) if (m_streamGrid) m_streamGrid->setLocalPreview(m_streamPublisher->group(), frame); }); } + qint64 engineUs = elapsed.nsecsElapsed() / 1000; if (m_streamPublishWindow) delete m_streamPublishWindow.data(); + qint64 removedUs = elapsed.nsecsElapsed() / 1000; m_streamPublishWindow = new StreamPublishWindow(m_streamPublisher, m_streamPublisher->active() ? m_streamPublisher->group() : group, this, m_db ? m_db->getUiState("stream_capture_settings") : QString()); + qint64 constructedUs = elapsed.nsecsElapsed() / 1000; connect(m_streamPublishWindow, &StreamPublishWindow::settingsChanged, this, [](const QString& settings) { postUiStateKv("stream_capture_settings", settings); }); if (returnTo) connect(m_streamPublishWindow, &StreamPublishWindow::closed, returnTo, [returnTo] { @@ -688,6 +693,12 @@ void MainWindow::showStreamPublisher(quint64 group, StreamGridWindow* returnTo) DEBUG_INFO(DEBUG_CATEGORY_STREAM, "desktop publisher controls opened group=%llx return_to_grid=%d", (unsigned long long)group, returnTo != nullptr); m_streamPublishWindow->show(); m_streamPublishWindow->raise(); m_streamPublishWindow->activateWindow(); + qint64 shownUs = elapsed.nsecsElapsed() / 1000; + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, + "desktop publisher UI group=%llx active=%d return_to_grid=%d engine_us=%lld remove_us=%lld construct_us=%lld show_us=%lld total_us=%lld", + (unsigned long long)group, m_streamPublisher->active(), returnTo != nullptr, (long long)engineUs, + (long long)(removedUs - engineUs), (long long)(constructedUs - removedUs), + (long long)(shownUs - constructedUs), (long long)shownUs); } void MainWindow::setupConnects() { diff --git a/tools/chatgui/src/stream_publish_engine.cpp b/tools/chatgui/src/stream_publish_engine.cpp index 1f70eedd..dd26def4 100644 --- a/tools/chatgui/src/stream_publish_engine.cpp +++ b/tools/chatgui/src/stream_publish_engine.cpp @@ -146,6 +146,8 @@ struct StreamPublishEngine::Impl { QVideoFrame previewFrame; QVideoFrame presentedPreview; int64_t lastImageCaptureAt = 0; + int64_t previewTickAt = 0, previewReportAt = 0, previewGapMax = 0, previewDispatchMax = 0; + unsigned previewUpdates = 0; // Диагностика GUI-предпросмотра; только GUI-поток. #endif }; @@ -164,12 +166,29 @@ StreamPublishEngine::StreamPublishEngine(QObject* parent) : QObject(parent), m(s connect(qGuiApp, &QGuiApplication::screenRemoved, this, &StreamPublishEngine::sourcesChanged); m_previewTimer.setTimerType(Qt::PreciseTimer); m_previewTimer.setInterval(33); connect(&m_previewTimer, &QTimer::timeout, this, [this] { - if (!m->running) return; + if (!m->running) { + m->previewTickAt = m->previewReportAt = m->previewGapMax = m->previewDispatchMax = 0; + m->previewUpdates = 0; return; + } + int64_t tickAt = monotonicUs(); + if (m->previewTickAt) m->previewGapMax = std::max(m->previewGapMax, tickAt - m->previewTickAt); + m->previewTickAt = tickAt; + if (!m->previewReportAt) m->previewReportAt = tickAt; QVideoFrame frame; { std::lock_guard guard(m->lock); - if (m->previewFrame == m->presentedPreview) return; - frame = m->presentedPreview = m->previewFrame; } - if (frame.isValid()) emit previewVideoChanged(QVariant::fromValue(frame)); + if (m->previewFrame != m->presentedPreview) frame = m->presentedPreview = m->previewFrame; } + if (frame.isValid()) { + int64_t dispatchAt = monotonicUs(); + emit previewVideoChanged(QVariant::fromValue(frame)); + m->previewDispatchMax = std::max(m->previewDispatchMax, monotonicUs() - dispatchAt); m->previewUpdates++; + } + if (tickAt - m->previewReportAt >= 1000000) { + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, + "desktop preview GUI id=%llu source_generation=%llu interval_us=%lld updates=%u tick_gap_max_us=%lld dispatch_max_us=%lld", + (unsigned long long)m->id, (unsigned long long)m->sourceGeneration, (long long)(tickAt - m->previewReportAt), + m->previewUpdates, (long long)m->previewGapMax, (long long)m->previewDispatchMax); + m->previewReportAt = tickAt; m->previewUpdates = 0; m->previewGapMax = m->previewDispatchMax = 0; + } }); m_previewTimer.start(); #endif diff --git a/tools/chatgui/src/streamplayer_window.cpp b/tools/chatgui/src/streamplayer_window.cpp index 23016652..f3cbf092 100644 --- a/tools/chatgui/src/streamplayer_window.cpp +++ b/tools/chatgui/src/streamplayer_window.cpp @@ -68,7 +68,7 @@ struct StreamPlayerWindow::Playback { uint64_t audioFrameStart = 0, shown = 0, underruns = 0, endFrames = UINT64_MAX; bool started = false, presenting = false, videoReady = false, ended = false, videoEnded = false; bool activeAudio = false, holdAudio = false, resync = false; - int64_t audioFedAt = 0, audioFedPts = -1, workerAt = 0; + int64_t audioFedAt = 0, audioFedPts = -1, workerAt = 0, guiAt = 0, guiGapMax = 0; ~Playback() { stream_playback_audio_destroy(sound); } uint64_t played(int64_t now) const { @@ -176,7 +176,10 @@ void StreamPlayerWindow::tick() { int64_t shownPts = -1, readyPts = -1, mediaPosition = -1, deviceLead = 0; { std::lock_guard guard(p.lock); - int64_t clock = p.clock(nowUs()); + int64_t now = nowUs(); + if (p.guiAt) p.guiGapMax = std::max(p.guiGapMax, now - p.guiAt); + p.guiAt = now; + int64_t clock = p.clock(now); while (p.started && !p.videos.empty() && p.videos.front().pts <= clock) { p.videoBytes -= static_cast(p.videos.front().image.sizeInBytes()); p.lastShownPts = p.videos.front().pts; image = std::move(p.videos.front().image); p.videos.pop_front(); @@ -239,6 +242,13 @@ void StreamPlayerWindow::decode() { int64_t deadline = nowUs() + 10000000, report = nowUs(), decoderProgress = -1, lastInputAt = -1; uint64_t reportedGaps = 0; int64_t gapReportAt = 0; + struct { + uint64_t loops = 0, video = 0, audio = 0, empty = 0; + int64_t codec = 0, codecMax = 0, convert = 0, convertMax = 0; + int64_t audioFeed = 0, audioFeedMax = 0; + int64_t pull = 0, pullMax = 0, sleep = 0, sleepMax = 0, loopMax = 0; + } work; + int64_t lastLoopAt = report; auto reset = [&](bool request) { avcodec_free_context(&decoder); av_packet_unref(packet); waitKey = true; finishing = eosSent = false; decoderProgress = lastInputAt = -1; @@ -285,7 +295,10 @@ void StreamPlayerWindow::decode() { if (!decoder) return; for (unsigned work = 0; work < 8 && p.running; work++) { { std::lock_guard guard(p.lock); if (p.videos.size() >= 2) return; } + int64_t codecAt = nowUs(); int result = avcodec_receive_frame(decoder, frame); + int64_t codecUs = nowUs() - codecAt; + work.codec += codecUs; work.codecMax = std::max(work.codecMax, codecUs); if (result == AVERROR(EAGAIN)) return; if (result == AVERROR_EOF) { std::lock_guard guard(p.lock); p.videoEnded = true; @@ -312,6 +325,7 @@ void StreamPlayerWindow::decode() { (unsigned long long)p.id, (long long)pts, (long long)p.decoderLead, (long long)(nowUs() - p.createdAt), (long long)(p.firstInputAt ? nowUs() - p.firstInputAt : -1), (long long)(p.ready - pts)); } if (pts < p.clock(nowUs()) - 100000) { discarded++; continue; } } + int64_t convertAt = nowUs(); converter = sws_getCachedContext(converter, frame->width, frame->height, (AVPixelFormat)frame->format, frame->width, frame->height, AV_PIX_FMT_RGB24, SWS_BILINEAR, nullptr, nullptr, nullptr); QImage image = video_frame_image(frame->width, frame->height); @@ -322,6 +336,8 @@ void StreamPlayerWindow::decode() { fail(text("Stream video conversion failed")); p.running = false; return; } if (videoFormat.rotation) image = image.transformed(QTransform().rotate(videoFormat.rotation)); + int64_t convertUs = nowUs() - convertAt; + work.convert += convertUs; work.convertMax = std::max(work.convertMax, convertUs); std::lock_guard guard(p.lock); p.videoBytes += (size_t)image.sizeInBytes(); p.videos.push_back({std::move(image), pts}); } @@ -329,6 +345,36 @@ void StreamPlayerWindow::decode() { if (!frame || !packet) fail(text("Stream decoder allocation failed")); else if (!gui_stream_open(p.id, p.group, p.source, p.epoch)) fail(text("Could not connect to the stream")); else while (p.running) { + int64_t loopAt = nowUs(); + work.loops++; work.loopMax = std::max(work.loopMax, loopAt - lastLoopAt); lastLoopAt = loopAt; + if (loopAt - report >= 1000000) { + double seconds = (loopAt - report) / 1000000.0; + std::lock_guard guard(p.lock); + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, + "desktop viewer work id=%llu interval_us=%lld loops=%llu video=%llu audio=%llu empty=%llu " + "codec_us=%lld/%lld convert_us=%lld/%lld audio_feed_us=%lld/%lld pull_us=%lld/%lld sleep_us=%lld/%lld " + "loop_max_us=%lld gui_gap_max_us=%lld gui_age_us=%lld decoded=%llu shown=%llu show_fps=%.1f " + "clock_us=%lld ready_us=%lld videoQ=%zu hold=%d underruns=%llu timing=total/max", + (unsigned long long)p.id, (long long)(loopAt - report), (unsigned long long)work.loops, + (unsigned long long)work.video, (unsigned long long)work.audio, (unsigned long long)work.empty, + (long long)work.codec, (long long)work.codecMax, (long long)work.convert, (long long)work.convertMax, + (long long)work.audioFeed, (long long)work.audioFeedMax, + (long long)work.pull, (long long)work.pullMax, (long long)work.sleep, (long long)work.sleepMax, + (long long)work.loopMax, (long long)p.guiGapMax, (long long)(p.guiAt ? nowUs() - p.guiAt : -1), + (unsigned long long)decoded, (unsigned long long)p.shown, (p.shown - reportedShown) / seconds, + (long long)p.position, (long long)p.ready, p.videos.size(), p.holdAudio, (unsigned long long)p.underruns); + DEBUG_DEBUG(DEBUG_CATEGORY_STREAM, + "desktop viewer id=%llu decoded=%llu discarded=%llu shown=%llu showFps=%.1f videoQ=%zu " + "clock=%lld reserve_us=%lld minimum_us=%lld tempo=%d lead_us=%lld underruns=%llu " + "ready_us=%lld shown_pts=%lld display_lag_us=%lld decoder_lead_us=%lld hold=%d", + (unsigned long long)p.id, (unsigned long long)decoded, (unsigned long long)discarded, + (unsigned long long)p.shown, (p.shown - reportedShown) / seconds, p.videos.size(), (long long)p.position, + (long long)p.timing.reserve_us, (long long)p.timing.minimum_us, p.timing.tempo_milli, + (long long)p.deviceLead, (unsigned long long)p.underruns, (long long)p.ready, + (long long)p.lastShownPts, (long long)(p.lastShownPts >= 0 ? p.position - p.lastShownPts : -1), + (long long)p.decoderLead, p.holdAudio); + work = {}; report = loopAt; reportedShown = p.shown; p.guiGapMax = 0; + } bool resync; Playback::AudioGap gap; { std::lock_guard guard(p.lock); resync = p.resync; p.workerAt = nowUs(); gap = p.audioGap; } @@ -349,7 +395,10 @@ void StreamPlayerWindow::decode() { bool space; { std::lock_guard guard(p.lock); space = p.videos.size() < 2; } if (space && decoder && (packet->size || (finishing && !eosSent))) { + int64_t codecAt = nowUs(); int sent = avcodec_send_packet(decoder, packet->size ? packet : nullptr); + int64_t codecUs = nowUs() - codecAt; + work.codec += codecUs; work.codecMax = std::max(work.codecMax, codecUs); if (sent == 0) { if (packet->size) { std::lock_guard guard(p.lock); @@ -395,10 +444,18 @@ void StreamPlayerWindow::decode() { } } StreamRecord record; - if (finishing || !gui_stream_pull(p.id, record, position, wantVideo, audioAhead)) { + int64_t pullAt = nowUs(); + bool received = !finishing && gui_stream_pull(p.id, record, position, wantVideo, audioAhead); + int64_t pullUs = nowUs() - pullAt; + work.pull += pullUs; work.pullMax = std::max(work.pullMax, pullUs); + if (!received) { + work.empty++; if (!gui_stream_ready()) { fail(text("Chat service is stopped")); break; } if ((!opened || waitKey) && nowUs() > deadline) { fail(text("Stream connection timed out")); break; } - std::this_thread::sleep_for(std::chrono::milliseconds(5)); continue; + int64_t sleepAt = nowUs(); + std::this_thread::sleep_for(std::chrono::milliseconds(5)); + int64_t sleepUs = nowUs() - sleepAt; + work.sleep += sleepUs; work.sleepMax = std::max(work.sleepMax, sleepUs); continue; } if (record.kind == StreamRecordKind::Opened) { opened = true; continue; } if (record.kind == StreamRecordKind::Gap) { reset(false); continue; } @@ -417,15 +474,20 @@ void StreamPlayerWindow::decode() { observe(); if (record.pts > INT64_MAX) { fail(text("Invalid stream timestamp")); break; } if (record.kind == StreamRecordKind::Audio) { + work.audio++; + int64_t audioAt = nowUs(); int result = 0; { std::lock_guard guard(p.lock); if (p.sound) result = stream_playback_audio_feed(p.sound, (int64_t)record.pts, reinterpret_cast(record.data.constData()), (size_t)record.data.size()); if (p.sound && result == 0) { p.audioFedAt = nowUs(); p.audioFedPts = (int64_t)record.pts; } } + int64_t audioUs = nowUs() - audioAt; + work.audioFeed += audioUs; work.audioFeedMax = std::max(work.audioFeedMax, audioUs); if (result == -2) reset(true); else if (result < 0) { fail(text("Stream audio decoder failed")); break; } continue; } + work.video++; if (revision != record.format.revision) { avcodec_free_context(&decoder); waitKey = true; revision = record.format.revision; decoderProgress = lastInputAt = -1; @@ -480,21 +542,6 @@ void StreamPlayerWindow::decode() { std::memcpy(packet->data, data, size); packet->pts = packet->dts = (int64_t)record.pts; if (lastInputAt < 0 || nowUs() - lastInputAt > 1000000) decoderProgress = nowUs(); - if (nowUs() - report >= 1000000) { - int64_t now = nowUs(); double seconds = (now - report) / 1000000.0; report = now; - std::lock_guard guard(p.lock); - DEBUG_DEBUG(DEBUG_CATEGORY_STREAM, - "desktop viewer id=%llu decoded=%llu discarded=%llu shown=%llu showFps=%.1f videoQ=%zu " - "clock=%lld reserve_us=%lld minimum_us=%lld tempo=%d lead_us=%lld underruns=%llu " - "ready_us=%lld shown_pts=%lld display_lag_us=%lld decoder_lead_us=%lld hold=%d", - (unsigned long long)p.id, (unsigned long long)decoded, (unsigned long long)discarded, - (unsigned long long)p.shown, (p.shown - reportedShown) / seconds, p.videos.size(), (long long)p.position, - (long long)p.timing.reserve_us, (long long)p.timing.minimum_us, p.timing.tempo_milli, - (long long)p.deviceLead, (unsigned long long)p.underruns, (long long)p.ready, - (long long)p.lastShownPts, (long long)(p.lastShownPts >= 0 ? p.position - p.lastShownPts : -1), - (long long)p.decoderLead, p.holdAudio); - reportedShown = p.shown; - } } avcodec_free_context(&decoder); av_frame_free(&frame); av_packet_free(&packet); if (converter) sws_freeContext(converter);