Permalink
Browse files

Merge pull request #2539 from popcornmix/new_stall2

[rbp] Some bug fixes, logging and tidying relating to buffering.
  • Loading branch information...
2 parents fc3986d + cca2d30 commit 802a856fc4cd6a0de80daa1b8d6b066691a9c8e4 @huceke huceke committed Apr 5, 2013
@@ -906,6 +906,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
@@ -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
@@ -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;
@@ -228,7 +228,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;
}
@@ -240,12 +240,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;
@@ -388,7 +388,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;
@@ -508,6 +508,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)))
@@ -521,7 +525,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())
@@ -581,6 +585,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));
}
@@ -589,7 +594,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();
@@ -618,8 +623,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;
@@ -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
@@ -357,7 +357,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);
@@ -384,26 +384,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;
}
@@ -461,8 +446,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))
{
@@ -490,10 +475,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));
}
@@ -502,7 +492,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();
@@ -525,6 +515,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)
{
@@ -839,6 +839,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
Oops, something went wrong.

0 comments on commit 802a856

Please sign in to comment.