From 7b449d638ee770448311a224403193632cc4a957 Mon Sep 17 00:00:00 2001 From: popcornmix Date: Tue, 14 Sep 2021 18:23:14 +0100 Subject: [PATCH] temp: copious video frame logging --- .../DVDCodecs/Video/DVDVideoCodecDRMPRIME.cpp | 39 +++++++++++++++++-- xbmc/cores/VideoPlayer/VideoPlayerVideo.cpp | 10 ++++- .../HwDecRender/VideoLayerBridgeDRMPRIME.cpp | 12 ++++++ .../VideoRenderers/RenderManager.cpp | 3 ++ 4 files changed, 58 insertions(+), 6 deletions(-) diff --git a/xbmc/cores/VideoPlayer/DVDCodecs/Video/DVDVideoCodecDRMPRIME.cpp b/xbmc/cores/VideoPlayer/DVDCodecs/Video/DVDVideoCodecDRMPRIME.cpp index 6b64c59b78d84..d28909e507a11 100644 --- a/xbmc/cores/VideoPlayer/DVDCodecs/Video/DVDVideoCodecDRMPRIME.cpp +++ b/xbmc/cores/VideoPlayer/DVDCodecs/Video/DVDVideoCodecDRMPRIME.cpp @@ -249,6 +249,8 @@ int CDVDVideoCodecDRMPRIME::GetBuffer(struct AVCodecContext* avctx, AVFrame* fra if (!buffer) return -1; + CLog::Log(LOGDEBUG, "CDVDVideoCodecDRMPRIME::{} - frame:{} buffer:{} size:{} fmt:{}", + __FUNCTION__, (void *)frame, (void *)buffer, size, (int)avctx->pix_fmt); frame->opaque = static_cast(buffer); frame->opaque_ref = av_buffer_create(nullptr, 0, ReleaseBuffer, frame->opaque, AV_BUFFER_FLAG_READONLY); @@ -611,6 +613,8 @@ bool CDVDVideoCodecDRMPRIME::SetPictureParams(VideoPicture* pVideoPicture) return false; } + CLog::Log(LOGDEBUG, "CDVDVideoCodecDRMPRIME::{} - videoBuffer:{} format:{} flags:{}", __FUNCTION__, + (void *)pVideoPicture->videoBuffer, static_cast(m_pFrame->format), pVideoPicture->iFlags); return true; } @@ -647,6 +651,8 @@ bool CDVDVideoCodecDRMPRIME::FilterOpen(const std::string& filters, bool test) { int result; + CLog::Log(LOGDEBUG, "CDVDVideoCodecDRMPRIME::FilterOpen - {} test:{}", filters, test); + if (m_pFilterGraph) FilterClose(); @@ -684,8 +690,8 @@ bool CDVDVideoCodecDRMPRIME::FilterOpen(const std::string& filters, bool test) char err[AV_ERROR_MAX_STRING_SIZE] = {}; av_strerror(result, err, AV_ERROR_MAX_STRING_SIZE); CLog::Log(LOGERROR, - "CDVDVideoCodecDRMPRIME::FilterOpen - avfilter_graph_create_filter: src: {} ({})", - err, result); + "CDVDVideoCodecDRMPRIME::FilterOpen({})- pix_fmt:{} args:{} avfilter_graph_create_filter: src: {} ({})", + filters, av_get_pix_fmt_name(m_pCodecContext->pix_fmt), args, err, result); return false; } @@ -808,7 +814,10 @@ void CDVDVideoCodecDRMPRIME::FilterClose() CDVDVideoCodec::VCReturn CDVDVideoCodecDRMPRIME::ProcessFilterIn() { + auto descriptor = reinterpret_cast(m_pFrame->data[0]); + CLog::Log(LOGDEBUG, "CDVDVideoCodecDRMPRIME::{} - av_buffersrc_add_frame fd:{}", __FUNCTION__, descriptor ? descriptor->objects[0].fd:-1); int ret = av_buffersrc_add_frame(m_pFilterIn, m_pFrame); + CLog::Log(LOGDEBUG, "CDVDVideoCodecDRMPRIME::{} - av_buffersrc_add_frame: {}", __FUNCTION__, ret); if (ret < 0) { char err[AV_ERROR_MAX_STRING_SIZE] = {}; @@ -823,7 +832,12 @@ CDVDVideoCodec::VCReturn CDVDVideoCodecDRMPRIME::ProcessFilterIn() CDVDVideoCodec::VCReturn CDVDVideoCodecDRMPRIME::ProcessFilterOut() { + CLog::Log(LOGDEBUG, "CDVDVideoCodecDRMPRIME::{} - av_buffersink_get_frame", __FUNCTION__); int ret = av_buffersink_get_frame(m_pFilterOut, m_pFilterFrame); + + auto descriptor = reinterpret_cast(m_pFilterFrame->data[0]); + CLog::Log(LOGDEBUG, "CDVDVideoCodecDRMPRIME::{} - av_buffersink_get_frame: fd:{} ret:{} pts:{} best:{}", + __FUNCTION__, descriptor ? descriptor->objects[0].fd:-1, ret, m_pFilterFrame->pts, m_pFilterFrame->best_effort_timestamp); if (ret == AVERROR(EAGAIN)) return VC_BUFFER; else if (ret == AVERROR_EOF) @@ -844,6 +858,7 @@ CDVDVideoCodec::VCReturn CDVDVideoCodecDRMPRIME::ProcessFilterOut() av_frame_unref(m_pFrame); av_frame_move_ref(m_pFrame, m_pFilterFrame); + CLog::Log(LOGDEBUG, "CDVDVideoCodecDRMPRIME::{} - returning pic", __FUNCTION__); return VC_PICTURE; } @@ -876,6 +891,7 @@ CDVDVideoCodec::VCReturn CDVDVideoCodecDRMPRIME::GetPicture(VideoPicture* pVideo if (m_pFilterGraph) { auto ret = ProcessFilterOut(); + CLog::Log(LOGDEBUG, "CDVDVideoCodecDRMPRIME::{} - ProcessFilterOut()={}", __FUNCTION__, ret); if (ret == VC_PICTURE) { if (!SetPictureParams(pVideoPicture)) @@ -888,7 +904,9 @@ CDVDVideoCodec::VCReturn CDVDVideoCodecDRMPRIME::GetPicture(VideoPicture* pVideo } } + CLog::Log(LOGDEBUG, "CDVDVideoCodecDRMPRIME::{} - avcodec_receive_frame", __FUNCTION__); int ret = avcodec_receive_frame(m_pCodecContext, m_pFrame); + if (ret == AVERROR(EAGAIN)) return VC_BUFFER; else if (ret == AVERROR_EOF) @@ -902,6 +920,9 @@ CDVDVideoCodec::VCReturn CDVDVideoCodecDRMPRIME::GetPicture(VideoPicture* pVideo return VC_ERROR; } + CLog::Log(LOGDEBUG, "CDVDVideoCodecDRMPRIME::{} - avcodec_receive_frame: format:{} hw:{} frame:{} buffer:{}", + __FUNCTION__, m_pFrame->format, IsSupportedHwFormat(static_cast(m_pFrame->format)), (void *)m_pFrame, m_pFrame->opaque); + if (IsSupportedHwFormat(static_cast(m_pFrame->format))) { } @@ -913,6 +934,11 @@ CDVDVideoCodec::VCReturn CDVDVideoCodecDRMPRIME::GetPicture(VideoPicture* pVideo m_pFrame->data[0] = reinterpret_cast(descriptor); } + auto descriptor = reinterpret_cast(m_pFrame->data[0]); + CLog::Log(LOGDEBUG, "CDVDVideoCodecDRMPRIME::{} - avcodec_receive_frame: fd:{} ret:{} int:{} tff:{}", + __FUNCTION__, descriptor ? descriptor->objects[0].fd:-1, ret, m_pFrame->interlaced_frame, m_pFrame->top_field_first); + + if (!m_processInfo.GetVideoInterlaced() && m_pFrame->interlaced_frame) m_processInfo.SetVideoInterlaced(true); @@ -937,14 +963,19 @@ CDVDVideoCodec::VCReturn CDVDVideoCodecDRMPRIME::GetPicture(VideoPicture* pVideo if (m_pFilterGraph) { - if (ProcessFilterIn() != VC_PICTURE) + auto ret = ProcessFilterIn(); + CLog::Log(LOGDEBUG, "CDVDVideoCodecDRMPRIME::{} - ProcessFilterIn()={}", __FUNCTION__, ret); + if (ret != VC_PICTURE) return VC_NONE; } } if (!SetPictureParams(pVideoPicture)) + { + CLog::Log(LOGERROR, "CDVDVideoCodecDRMPRIME::{}={}", __FUNCTION__, VC_ERROR); return VC_ERROR; - + } + CLog::Log(LOGDEBUG, "CDVDVideoCodecDRMPRIME::{}={}", __FUNCTION__, VC_PICTURE); return VC_PICTURE; } diff --git a/xbmc/cores/VideoPlayer/VideoPlayerVideo.cpp b/xbmc/cores/VideoPlayer/VideoPlayerVideo.cpp index 8cfe882265f42..4d36fbe2a56ae 100644 --- a/xbmc/cores/VideoPlayer/VideoPlayerVideo.cpp +++ b/xbmc/cores/VideoPlayer/VideoPlayerVideo.cpp @@ -331,8 +331,10 @@ void CVideoPlayerVideo::Process() iQueueTimeOut = 1; } + CLog::Log(LOGDEBUG,"{} - GetMessage timeout:{}", __FUNCTION__, iQueueTimeOut); std::shared_ptr pMsg; MsgQueueReturnCode ret = GetMessage(pMsg, iQueueTimeOut, iPriority); + CLog::Log(LOGDEBUG,"{} - GetMessage ret:{}", __FUNCTION__, ret); onlyPrioMsgs = false; @@ -875,13 +877,14 @@ CVideoPlayerVideo::EOutputState CVideoPlayerVideo::OutputPicture(const VideoPict iPlayingClock = m_pClock->GetClock(iCurrentClock, false); // snapshot current clock - if (m_speed < 0) - { double renderPts; int queued, discard; int lateframes; double inputPts = m_droppingStats.m_lastPts; m_renderManager.GetStats(lateframes, renderPts, queued, discard); + + if (m_speed < 0) + { if (pPicture->pts > renderPts || queued > 0) { if (inputPts >= renderPts) @@ -911,7 +914,9 @@ CVideoPlayerVideo::EOutputState CVideoPlayerVideo::OutputPicture(const VideoPict // don't wait when going ff if (m_speed > DVD_PLAYSPEED_NORMAL) maxWaitTime = std::max(timeToDisplay, 0); + CLog::Log(LOGDEBUG,"{} - pts:{} {} {} {} queued:{} speed:{}", __FUNCTION__, pPicture->pts, inputPts, renderPts, iPlayingClock, queued, m_speed); int buffer = m_renderManager.WaitForBuffer(m_bAbortOutput, maxWaitTime); + CLog::Log(LOGDEBUG,"{} - pts:{} {} {} {} queued:{} speed:{} buffer:{}", __FUNCTION__, pPicture->pts, inputPts, renderPts, iPlayingClock, queued, m_speed, buffer); if (buffer < 0) { if (m_speed != DVD_PLAYSPEED_PAUSE) @@ -932,6 +937,7 @@ CVideoPlayerVideo::EOutputState CVideoPlayerVideo::OutputPicture(const VideoPict return OUTPUT_DROPPED; } + CLog::Log(LOGDEBUG, "{} - normal return", __FUNCTION__); return OUTPUT_NORMAL; } diff --git a/xbmc/cores/VideoPlayer/VideoRenderers/HwDecRender/VideoLayerBridgeDRMPRIME.cpp b/xbmc/cores/VideoPlayer/VideoRenderers/HwDecRender/VideoLayerBridgeDRMPRIME.cpp index 3814f968a73b7..9d8c777fbc38e 100644 --- a/xbmc/cores/VideoPlayer/VideoRenderers/HwDecRender/VideoLayerBridgeDRMPRIME.cpp +++ b/xbmc/cores/VideoPlayer/VideoRenderers/HwDecRender/VideoLayerBridgeDRMPRIME.cpp @@ -97,7 +97,10 @@ void CVideoLayerBridgeDRMPRIME::Release(CVideoBufferDRMPRIME* buffer) bool CVideoLayerBridgeDRMPRIME::Map(CVideoBufferDRMPRIME* buffer) { if (buffer->m_fb_id) + { + CLog::Log(LOGDEBUG, "CVideoLayerBridgeDRMPRIME::{} id:{} already set", __FUNCTION__, buffer->m_fb_id); return true; + } if (!buffer->AcquireDescriptor()) { @@ -148,6 +151,9 @@ bool CVideoLayerBridgeDRMPRIME::Map(CVideoBufferDRMPRIME* buffer) ret = drmModeAddFB2WithModifiers(m_DRM->GetFileDescriptor(), buffer->GetWidth(), buffer->GetHeight(), layer->format, handles, pitches, offsets, modifier, &buffer->m_fb_id, flags); + + CLog::Log(LOGDEBUG, "CVideoLayerBridgeDRMPRIME::{} fd:{} id:{}", __FUNCTION__, descriptor->objects[0].fd, buffer->m_fb_id); + if (ret < 0) { CLog::Log(LOGERROR, "CVideoLayerBridgeDRMPRIME::{} - failed to add fb {}, ret = {}", @@ -156,11 +162,15 @@ bool CVideoLayerBridgeDRMPRIME::Map(CVideoBufferDRMPRIME* buffer) } Acquire(buffer); + + CLog::Log(LOGDEBUG, "CVideoLayerBridgeDRMPRIME::{} released", __FUNCTION__); return true; } void CVideoLayerBridgeDRMPRIME::Unmap(CVideoBufferDRMPRIME* buffer) { + CLog::Log(LOGDEBUG, "CVideoLayerBridgeDRMPRIME::{} - id:{}", __FUNCTION__, buffer->m_fb_id); + if (buffer->m_fb_id) { drmModeRmFB(m_DRM->GetFileDescriptor(), buffer->m_fb_id); @@ -333,6 +343,8 @@ void CVideoLayerBridgeDRMPRIME::SetVideoPlane(CVideoBufferDRMPRIME* buffer, cons void CVideoLayerBridgeDRMPRIME::UpdateVideoPlane() { + CLog::Log(LOGDEBUG, "CVideoLayerBridgeDRMPRIME::{} - id:{}", __FUNCTION__, m_buffer ? (int)m_buffer->m_fb_id : -1); + if (!m_buffer || !m_buffer->m_fb_id) return; diff --git a/xbmc/cores/VideoPlayer/VideoRenderers/RenderManager.cpp b/xbmc/cores/VideoPlayer/VideoRenderers/RenderManager.cpp index 617649f02fb71..810aede7a39e4 100644 --- a/xbmc/cores/VideoPlayer/VideoRenderers/RenderManager.cpp +++ b/xbmc/cores/VideoPlayer/VideoRenderers/RenderManager.cpp @@ -1092,11 +1092,14 @@ int CRenderManager::WaitForBuffer(volatile std::atomic_bool&bStop, int timeout) if (sleeptime < 0ms) sleeptime = 0ms; sleeptime = std::min(sleeptime, 20ms); + CLog::Log(LOGDEBUG, "CRenderManager::{} - sleep:{} {} {} free:{} queued:{} m_discard:{}", __FUNCTION__, + sleeptime, presenttime, clock, m_free.size(), m_queued.size(), m_discard.size()); m_presentevent.wait(lock, sleeptime); DiscardBuffer(); return 0; } + CLog::Log(LOGDEBUG, "CRenderManager::{} - free:{} queued:{} m_discard:{}", __FUNCTION__, m_free.size(), m_queued.size(), m_discard.size()); XbmcThreads::EndTime endtime(timeout); while(m_free.empty()) {