[rbp] Some bug fixes, logging and tidying relating to buffering.

xbmc/cores/omxplayer/OMXAudio.cpp

@@ -908,6 +908,7 @@ unsigned int COMXAudio::AddPackets(const void* data, unsigned int len, double dt
       omx_err = m_omx_decoder.EmptyThisBuffer(omx_buffer);
       if (omx_err == OMX_ErrorNone)
       {
+        //CLog::Log(LOGINFO, "AudiD: dts:%.0f pts:%.0f size:%d\n", dts, pts, len);
         break;
       }
       else

xbmc/cores/omxplayer/OMXAudio.h

@@ -94,6 +94,7 @@ class COMXAudio
   unsigned int SyncAC3(BYTE* pData, unsigned int iSize);
 
   bool BadState() { return !m_Initialized; };
+  unsigned int GetAudioRenderingLatency();
 
 private:
   IAudioCallback* m_pCallback;
@@ -148,7 +149,6 @@ class COMXAudio
   CAEChannelInfo    GetChannelLayout(AEAudioFormat format);
 
   void CheckOutputBufferSize(void **buffer, int *oldSize, int newSize);
-  unsigned int GetAudioRenderingLatency();
   CCriticalSection m_critSection;
 };
 #endif

xbmc/cores/omxplayer/OMXPlayer.cpp

@@ -433,8 +433,6 @@ COMXPlayer::COMXPlayer(IPlayerCallback &callback)
   m_EdlAutoSkipMarkers.Clear();
 
   memset(&m_SpeedState, 0, sizeof(m_SpeedState));
-
-  m_messenger.Init();
 }
 
 COMXPlayer::~COMXPlayer()
@@ -559,6 +557,8 @@ void COMXPlayer::OnStartup()
   m_CurrentSubtitle.Clear();
   m_CurrentTeletext.Clear();
 
+  m_messenger.Init();
+
   CUtil::ClearTempFonts();
 }
 
@@ -721,7 +721,7 @@ void COMXPlayer::OpenDefaultStreams(bool reset)
   for(OMXSelectionStreams::iterator it = streams.begin(); it != streams.end() && !valid; ++it)
   {
     if(OpenVideoStream(it->id, it->source, reset))
-      valid = true;;
+      valid = true;
   }
   if(!valid)
     CloseVideoStream(true);
@@ -1064,6 +1064,22 @@ void COMXPlayer::Process()
 
   while (!m_bAbortRequest)
   {
+    #ifdef _DEBUG
+    char response[80];
+    static unsigned count;
+    if ((count++ & 15) == 0)
+    {
+      vc_gencmd(response, sizeof response, "render_bar 4 video_fifo %d %d %d %d",
+            m_player_video.GetDecoderBufferSize()-m_player_video.GetDecoderFreeSpace(),
+            0 , 0, m_player_video.GetDecoderBufferSize());
+      vc_gencmd(response, sizeof response, "render_bar 5 audio_fifo %d %d %d %d",
+            (int)(100.0*m_player_audio.GetDelay()), 0, 0, 100*AUDIO_BUFFER_SECONDS);
+      vc_gencmd(response, sizeof response, "render_bar 6 video_queue %d %d %d %d",
+            m_player_video.GetLevel(), 0, 0, 100);
+      vc_gencmd(response, sizeof response, "render_bar 7 audio_queue %d %d %d %d",
+            m_player_audio.GetLevel(), 0, 0, 100);
+    }
+    #endif
     // handle messages send to this thread, like seek or demuxer reset requests
     HandleMessages();
 
@@ -1075,6 +1091,7 @@ void COMXPlayer::Process()
     {
       if (OpenInputStream() == false)
       {
+        CLog::Log(LOGERROR, "%s - Closing stream due to OpenInputStream()", __FUNCTION__);
         m_bAbortRequest = true;
         break;
       }
@@ -1091,6 +1108,7 @@ void COMXPlayer::Process()
 
       if (OpenDemuxStream() == false)
       {
+        CLog::Log(LOGERROR, "%s - Closing stream due to OpenDemuxStream()", __FUNCTION__);
         m_bAbortRequest = true;
         break;
       }
@@ -1120,6 +1138,7 @@ void COMXPlayer::Process()
     // OMX emergency exit
     if(HasAudio() && m_player_audio.BadState())
     {
+      CLog::Log(LOGERROR, "%s - Closing stream due to m_player_audio.BadState()", __FUNCTION__);
       m_bAbortRequest = true;
       break;
     }
@@ -1751,6 +1770,7 @@ bool COMXPlayer::CheckPlayerInit(COMXCurrentStream& current, unsigned int source
 
 void COMXPlayer::UpdateCorrection(DemuxPacket* pkt, double correction)
 {
+  //CLog::Log(LOGINFO,"%s: %d dts:%.0f pts:%.0f s:%d c:%.0f (%d,%d)", __func__, (int)pkt->iStreamId, pkt->dts, pkt->pts, pkt->iSize, correction, pkt->dts==DVD_NOPTS_VALUE, pkt->pts==DVD_NOPTS_VALUE);
   if(pkt->dts != DVD_NOPTS_VALUE) pkt->dts -= correction;
   if(pkt->pts != DVD_NOPTS_VALUE) pkt->pts -= correction;
 }
@@ -2107,7 +2127,7 @@ void COMXPlayer::HandleMessages()
         CLog::Log(LOGDEBUG, "demuxer seek to: %d", time);
         if (m_pDemuxer && m_pDemuxer->SeekTime(time, msg.GetBackward(), &start))
         {
-          CLog::Log(LOGDEBUG, "demuxer seek to: %d, success", time);
+          CLog::Log(LOGDEBUG, "demuxer seek to: %.0f, success", start);
           if(m_pSubtitleDemuxer)
           {
             if(!m_pSubtitleDemuxer->SeekTime(time, msg.GetBackward()))
@@ -2271,7 +2291,7 @@ void COMXPlayer::HandleMessages()
         }
 
         // if playspeed is different then DVD_PLAYSPEED_NORMAL or DVD_PLAYSPEED_PAUSE
-        // audioplayer, stops outputing audio to audiorendere, but still tries to
+        // audioplayer, stops outputing audio to audiorender, but still tries to
         // sleep an correct amount for each packet
         // videoplayer just plays faster after the clock speed has been increased
         // 1. disable audio
@@ -2842,6 +2862,7 @@ int64_t COMXPlayer::GetTime()
     if(offset >  limit) offset =  limit;
     if(offset < -limit) offset = -limit;
   }
+  //{CLog::Log(LOGINFO, "%s: time:%.2f stamp:%.2f dts:%d m:%d (p:%d,c:%d) =%llu", __func__, (double)m_State.time, (double)m_State.timestamp, (int)DVD_TIME_TO_MSEC(m_State.dts + m_offset_pts), (int)DVD_TIME_TO_MSEC(m_av_clock.OMXMediaTime()), (int)m_playSpeed, (int)m_caching, llrint(m_State.time + DVD_TIME_TO_MSEC(offset)));}
   return llrint(m_State.time + DVD_TIME_TO_MSEC(offset));
 }
 
@@ -2876,11 +2897,17 @@ bool COMXPlayer::OpenAudioStream(int iStream, int source, bool reset)
   CLog::Log(LOGNOTICE, "Opening audio stream: %i source: %i", iStream, source);
 
   if (!m_pDemuxer)
+  {
+    CLog::Log(LOGWARNING, "Opening audio stream: no demuxer");
     return false;
+  }
 
   CDemuxStream* pStream = m_pDemuxer->GetStream(iStream);
   if (!pStream || pStream->disabled)
+  {
+    CLog::Log(LOGWARNING, "Opening audio stream: pStream=%p disabled=%d", pStream, pStream ? pStream->disabled:0);
     return false;
+  }
 
   if( m_CurrentAudio.id < 0 &&  m_CurrentVideo.id >= 0 )
   {
@@ -2937,11 +2964,17 @@ bool COMXPlayer::OpenVideoStream(int iStream, int source, bool reset)
   CLog::Log(LOGNOTICE, "Opening video stream: %i source: %i", iStream, source);
 
   if (!m_pDemuxer)
+  {
+    CLog::Log(LOGWARNING, "Opening video stream: no demuxer");
     return false;
+  }
 
   CDemuxStream* pStream = m_pDemuxer->GetStream(iStream);
   if(!pStream || pStream->disabled)
+  {
+    CLog::Log(LOGWARNING, "Opening video stream: pStream=%p disabled=%d", pStream, pStream ? pStream->disabled:0);
     return false;
+  }
   pStream->SetDiscard(AVDISCARD_NONE);
 
   CDVDStreamInfo hint(*pStream, true);
@@ -3222,6 +3255,9 @@ bool COMXPlayer::CloseTeletextStream(bool bWaitForBuffers)
 void COMXPlayer::FlushBuffers(bool queued, double pts, bool accurate)
 {
   double startpts;
+
+  CLog::Log(LOGNOTICE, "FlushBuffers: q:%d pts:%.0f a:%d", queued, pts, accurate);
+
   if(accurate)
     startpts = pts;
   else
@@ -3780,7 +3816,7 @@ bool COMXPlayer::GetCurrentSubtitle(CStdString& strSubtitle)
   if (m_pInputStream && m_pInputStream->IsStreamType(DVDSTREAM_TYPE_DVD))
     return false;
 
-  double pts = m_av_clock.OMXMediaTime(false, false);
+  double pts = m_av_clock.OMXMediaTime(false);
 
   m_player_subtitle.GetCurrentSubtitle(strSubtitle, pts - m_player_video.GetSubtitleDelay());
 
@@ -3977,7 +4013,7 @@ void COMXPlayer::UpdatePlayState(double timeout)
     else 
       // TODO : workaround until omx clock handling is rewritten
       if(m_playSpeed == DVD_PLAYSPEED_NORMAL)
-        state.time     = DVD_TIME_TO_MSEC(m_av_clock.OMXMediaTime(true, true));
+        state.time     = DVD_TIME_TO_MSEC(m_av_clock.OMXMediaTime(true));
       else
         state.time     = DVD_TIME_TO_MSEC(state.dts + m_offset_pts);
     state.time_total = m_pDemuxer->GetStreamLength();
@@ -4082,6 +4118,7 @@ void COMXPlayer::UpdatePlayState(double timeout)
     state.cache_bytes = 0;
 
   state.timestamp = m_av_clock.GetAbsoluteClock();
+  //{CLog::Log(LOGINFO, "%s: time:%.2f stamp:%.2f dts:%d m:%d (p:%d,c:%d) =%llu", __func__, (double)state.time, (double)state.timestamp, (int)DVD_TIME_TO_MSEC(state.dts + m_offset_pts), (int)DVD_TIME_TO_MSEC(m_av_clock.OMXMediaTime()), (int)m_playSpeed, (int)m_caching, llrint(state.time + DVD_TIME_TO_MSEC(offset)));}
 
   CSingleLock lock(m_StateSection);
   m_StateInput = state;

xbmc/cores/omxplayer/OMXPlayerAudio.cpp

@@ -213,7 +213,7 @@ void OMXPlayerAudio::HandleSyncError(double duration)
     m_skipdupcount = 0;
     m_error = 0;
     m_syncclock = false;
-    m_errortime = m_av_clock->CurrentHostCounter();
+    m_errortime = CurrentHostCounter();
 
     return;
   }
@@ -225,12 +225,12 @@ void OMXPlayerAudio::HandleSyncError(double duration)
     m_integral = 0;
     m_skipdupcount = 0;
     m_error = 0;
-    m_errortime = m_av_clock->CurrentHostCounter();
+    m_errortime = CurrentHostCounter();
     return;
   }
 
   //check if measured error for 1 second
-  now = m_av_clock->CurrentHostCounter();
+  now = CurrentHostCounter();
   if ((now - m_errortime) >= m_freq)
   {
     m_errortime = now;
@@ -373,7 +373,7 @@ bool OMXPlayerAudio::Decode(DemuxPacket *pkt, bool bDropPacket)
         if(m_flush)
           break;
 
-        if(m_omxAudio.GetSpace() < (unsigned int)pkt->iSize)
+        if(m_omxAudio.GetSpace() < (unsigned int)decoded_size)
         {
           Sleep(10);
           continue;
@@ -493,6 +493,10 @@ void OMXPlayerAudio::Process()
       DemuxPacket* pPacket = ((CDVDMsgDemuxerPacket*)pMsg)->GetPacket();
       bool bPacketDrop     = ((CDVDMsgDemuxerPacket*)pMsg)->GetPacketDrop();
 
+      #ifdef _DEBUG
+      CLog::Log(LOGINFO, "Audio: dts:%.0f pts:%.0f size:%d (s:%d f:%d d:%d l:%d) s:%d %d/%d late:%d,%d", pPacket->dts, pPacket->pts,
+           (int)pPacket->iSize, m_started, m_flush, bPacketDrop, m_stalled, m_speed, 0, 0, (int)m_omxAudio.GetAudioRenderingLatency(), (int)m_hints_current.samplerate);
+      #endif
       if(Decode(pPacket, m_speed > DVD_PLAYSPEED_NORMAL || m_speed < 0 || bPacketDrop))
       {
         if (m_stalled && (m_omxAudio.GetCacheTime() > (AUDIO_BUFFER_SECONDS * 0.75f)))
@@ -506,7 +510,7 @@ void OMXPlayerAudio::Process()
       // hard unlock audio out buffering
       clock_gettime(CLOCK_REALTIME, &m_endtime);
       //int iLevel = min(99,m_messageQueue.GetLevel() + MathUtils::round_int(100.0/8.0*GetCacheTime()));
-      if(/*iLevel < 10 &&*/ m_stalled && (m_endtime.tv_sec - m_starttime.tv_sec) > 1)
+      if(/*iLevel < 10 &&*/ m_stalled && m_av_clock->OMXAudioBuffer() && (m_endtime.tv_sec - m_starttime.tv_sec) > 1)
       {
         m_stalled = false;
         if(m_av_clock->HasVideo() && m_av_clock->OMXAudioBuffer())
@@ -566,6 +570,7 @@ void OMXPlayerAudio::Process()
     }
     else if (pMsg->IsType(CDVDMsg::PLAYER_STARTED))
     {
+      CLog::Log(LOGDEBUG, "COMXPlayerAudio - CDVDMsg::PLAYER_STARTED %d", m_started);
       if(m_started)
         m_messageParent.Put(new CDVDMsgInt(CDVDMsg::PLAYER_STARTED, DVDPLAYER_AUDIO));
     }
@@ -574,7 +579,7 @@ void OMXPlayerAudio::Process()
       COMXPlayer::SPlayerState& state = ((CDVDMsgType<COMXPlayer::SPlayerState>*)pMsg)->m_value;
 
       if(state.time_src == COMXPlayer::ETIMESOURCE_CLOCK)
-        state.time      = DVD_TIME_TO_MSEC(m_av_clock->OMXMediaTime(true, true));
+        state.time      = DVD_TIME_TO_MSEC(m_av_clock->OMXMediaTime(true));
         //state.time      = DVD_TIME_TO_MSEC(m_av_clock->GetClock(state.timestamp) + state.time_offset);
       else
         state.timestamp = m_av_clock->GetAbsoluteClock();
@@ -603,8 +608,11 @@ void OMXPlayerAudio::Process()
     }
     else if (pMsg->IsType(CDVDMsg::PLAYER_SETSPEED))
     {
-      CLog::Log(LOGDEBUG, "COMXPlayerAudio - CDVDMsg::PLAYER_SETSPEED");
-      m_speed = static_cast<CDVDMsgInt*>(pMsg)->m_value;
+      if (m_speed != static_cast<CDVDMsgInt*>(pMsg)->m_value)
+      {
+        m_speed = static_cast<CDVDMsgInt*>(pMsg)->m_value;
+        CLog::Log(LOGDEBUG, "COMXPlayerAudio - CDVDMsg::PLAYER_SETSPEED %d", m_speed);
+      }
       if (m_speed != DVD_PLAYSPEED_NORMAL)
       {
         m_syncclock = true;

xbmc/cores/omxplayer/OMXPlayerAudio.h

@@ -57,7 +57,7 @@ class OMXPlayerAudio : public CThread
   AEAudioFormat             m_format;
   CAEChannelInfo            m_channelLayout;
   COMXAudioCodecOMX         *m_pAudioCodec;
-  unsigned int              m_speed;
+  int                       m_speed;
   bool                      m_silence;
   double                    m_audioClock;
   double m_error;    //last average error

xbmc/cores/omxplayer/OMXPlayerVideo.cpp

@@ -351,7 +351,7 @@ void OMXPlayerVideo::Output(int iGroupId, double pts, bool bDropPacket)
   if (!CThread::m_bStop && m_av_clock->GetAbsoluteClock(false) < m_iSleepEndTime + DVD_MSEC_TO_TIME(500))
     return;
 
-  double pts_media = m_av_clock->OMXMediaTime(false, false);
+  double pts_media = m_av_clock->OMXMediaTime(false);
   ProcessOverlays(iGroupId, pts_media);
 
   g_renderManager.FlipPage(CThread::m_bStop, m_iSleepEndTime / DVD_TIME_BASE, -1, FS_NONE);
@@ -378,26 +378,11 @@ void OMXPlayerVideo::Process()
 
     if (MSGQ_IS_ERROR(ret) || ret == MSGQ_ABORT)
     {
-      CLog::Log(LOGERROR, "Got MSGQ_ABORT or MSGO_IS_ERROR return true");
+      CLog::Log(LOGERROR, "OMXPlayerVideo: Got MSGQ_IS_ERROR(%d) Aborting", (int)ret);
       break;
     }
     else if (ret == MSGQ_TIMEOUT)
     {
-      // if we only wanted priority messages, this isn't a stall
-      if( iPriority )
-        continue;
-
-      //Okey, start rendering at stream fps now instead, we are likely in a stillframe
-      if( !m_stalled )
-      {
-        if(m_started)
-          CLog::Log(LOGINFO, "COMXPlayerVideo - Stillframe detected, switching to forced %f fps", m_fFrameRate);
-        m_stalled = true;
-        pts += frametime*4;
-      }
-
-      pts += frametime;
-
       continue;
     }
 
@@ -455,8 +440,8 @@ void OMXPlayerVideo::Process()
     }
     else if (pMsg->IsType(CDVDMsg::VIDEO_SET_ASPECT))
     {
-      CLog::Log(LOGDEBUG, "COMXPlayerVideo - CDVDMsg::VIDEO_SET_ASPECT");
       m_fForcedAspectRatio = *((CDVDMsgDouble*)pMsg);
+      CLog::Log(LOGDEBUG, "COMXPlayerVideo - CDVDMsg::VIDEO_SET_ASPECT %.2f", m_fForcedAspectRatio);
     }
     else if (pMsg->IsType(CDVDMsg::GENERAL_RESET))
     {
@@ -484,10 +469,15 @@ void OMXPlayerVideo::Process()
     }
     else if (pMsg->IsType(CDVDMsg::PLAYER_SETSPEED))
     {
-      m_speed = static_cast<CDVDMsgInt*>(pMsg)->m_value;
+      if (m_speed != static_cast<CDVDMsgInt*>(pMsg)->m_value)
+      {
+        m_speed = static_cast<CDVDMsgInt*>(pMsg)->m_value;
+        CLog::Log(LOGDEBUG, "COMXPlayerVideo - CDVDMsg::PLAYER_SETSPEED %d", m_speed);
+      }
     }
     else if (pMsg->IsType(CDVDMsg::PLAYER_STARTED))
     {
+      CLog::Log(LOGDEBUG, "COMXPlayerVideo - CDVDMsg::PLAYER_STARTED %d", m_started);
       if(m_started)
         m_messageParent.Put(new CDVDMsgInt(CDVDMsg::PLAYER_STARTED, DVDPLAYER_VIDEO));
     }
@@ -496,7 +486,7 @@ void OMXPlayerVideo::Process()
       COMXPlayer::SPlayerState& state = ((CDVDMsgType<COMXPlayer::SPlayerState>*)pMsg)->m_value;
 
       if(state.time_src == COMXPlayer::ETIMESOURCE_CLOCK)
-        state.time      = DVD_TIME_TO_MSEC(m_av_clock->OMXMediaTime(true, true));
+        state.time      = DVD_TIME_TO_MSEC(m_av_clock->OMXMediaTime(true));
         //state.time      = DVD_TIME_TO_MSEC(m_av_clock->GetClock(state.timestamp) + state.time_offset);
       else
         state.timestamp = m_av_clock->GetAbsoluteClock();
@@ -519,6 +509,10 @@ void OMXPlayerVideo::Process()
       DemuxPacket* pPacket = ((CDVDMsgDemuxerPacket*)pMsg)->GetPacket();
       bool bPacketDrop     = ((CDVDMsgDemuxerPacket*)pMsg)->GetPacketDrop();
 
+      #ifdef _DEBUG
+      CLog::Log(LOGINFO, "Video: dts:%.0f pts:%.0f size:%d (s:%d f:%d d:%d l:%d) s:%d %d/%d late:%d\n", pPacket->dts, pPacket->pts, 
+          (int)pPacket->iSize, m_started, m_flush, bPacketDrop, m_stalled, m_speed, 0, 0, m_av_clock->OMXLateCount(1));
+      #endif
       if (m_messageQueue.GetDataSize() == 0
       ||  m_speed < 0)
       {

xbmc/cores/omxplayer/OMXVideo.cpp

@@ -835,6 +835,7 @@ int COMXVideo::Decode(uint8_t *pData, int iSize, double dts, double pts)
         omx_err = m_omx_decoder.EmptyThisBuffer(omx_buffer);
         if (omx_err == OMX_ErrorNone)
         {
+          //CLog::Log(LOGINFO, "VideD: dts:%.0f pts:%.0f size:%d)\n", dts, pts, iSize);
           break;
         }
         else