temp: copious video frame logging

popcornmix · Oct 24, 2021 · 7b449d6 · 7b449d6
1 parent 67b70de
commit 7b449d6
Show file tree

Hide file tree

Showing 4 changed files with 58 additions and 6 deletions.
diff --git 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<void*>(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<AVPixelFormat>(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<AVDRMFrameDescriptor*>(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<AVDRMFrameDescriptor*>(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<AVPixelFormat>(m_pFrame->format)), (void *)m_pFrame, m_pFrame->opaque);
+
   if (IsSupportedHwFormat(static_cast<AVPixelFormat>(m_pFrame->format)))
   {
   }
@@ -913,6 +934,11 @@ CDVDVideoCodec::VCReturn CDVDVideoCodecDRMPRIME::GetPicture(VideoPicture* pVideo
     m_pFrame->data[0] = reinterpret_cast<uint8_t*>(descriptor);
   }
 
+  auto descriptor = reinterpret_cast<AVDRMFrameDescriptor*>(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
@@ -331,8 +331,10 @@ void CVideoPlayerVideo::Process()
       iQueueTimeOut = 1;
     }
 
+    CLog::Log(LOGDEBUG,"{} - GetMessage timeout:{}", __FUNCTION__, iQueueTimeOut);
     std::shared_ptr<CDVDMsg> 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
@@ -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
@@ -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())
   {