Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[VideoPlayer] Flush streamplayers if abort is requested #15459

Merged
merged 1 commit into from Feb 10, 2019

Conversation

peak3d
Copy link
Contributor

@peak3d peak3d commented Feb 7, 2019

Description

Flush VideoPlayer's (sub) players (video / audio / subtitle ...) when closing a stream.

Motivation and Context

I ran regulary into the situation that stopping a video stream takes long time.
In one of my DVD iso's I have to wait for example ~ 15secs if I stop playback during legal notice.

In kodi log you see this:

14:56:44.982 T:15216 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
14:56:54.210 T:11328 WARNING: Previous line repeats 175 times.

Reason is that sub-players are not notified that abort is requested, and e.g. VideoPlayer tries to render frames while VideoPlayer is waiting for finalization.

This PR notifies sub-players that abort is requested using Flush().

How Has This Been Tested?

Very long wait for stream termination:

Types of change

  • Bug fix (non-breaking change which fixes an issue)
  • Clean up (non-breaking change which removes non-working, unmaintained functionality)
  • Improvement (non-breaking change which improves existing functionality)
  • New feature (non-breaking change which adds functionality)
  • Breaking change (fix or feature that will cause existing functionality to change)
  • Cosmetic change (non-breaking change that doesn't touch code)
  • None of the above (please explain below)

@peak3d peak3d added Type: Improvement non-breaking change which improves existing functionality Component: Video v18 Leia labels Feb 7, 2019
@peak3d peak3d added this to the Leia 18.1-rc1 milestone Feb 7, 2019
@FernetMenta
Copy link
Contributor

Reason is that sub-players are not notified that abort is requested

This is not correct. CVideoPlayer::OnExit calls CloseStream of subplayers. An extra flush should not be required.

void CVideoPlayer::FlushPlayer(bool sync)
{
CLog::Log(LOGNOTICE, "CVideoPlayer::FlushPlayer()");
m_VideoPlayerAudio->Flush(sync);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

those must only be called by videoplayer's thread.

@peak3d
Copy link
Contributor Author

peak3d commented Feb 7, 2019

VP::OnExit is not yet called, because of this the subplayers are not notified:

7:31:47.749 T:4516   DEBUG: CRenderManager::Configure - 6
17:31:47.750 T:4516 WARNING: CWinRenderer::UpdateVideoFilter: chosen scaling method 1 is not supported by renderer
17:31:47.751 T:10260   DEBUG: CApplication::OnAVChange: CApplication::OnAVChange
17:31:47.751 T:17616   DEBUG: CVideoPlayer::HandleMessages - player started 2
17:31:47.751 T:4516   DEBUG: CWinShader::LoadEffect: loading shader special://xbmc/system/shaders/output_d3d.fx
17:31:47.752 T:17616   DEBUG: VideoPlayer::Sync - Video - pts: 316983.333333, cache: 50000.000000, totalcache: 100000.000000
17:31:47.752 T:17616 WARNING: CDVDMessageQueue(audio)::Put MSGQ_NOT_INITIALIZED
17:31:47.753 T:20844   DEBUG: CVideoPlayerVideo - CDVDMsg::GENERAL_RESYNC(216983.333333)
17:31:47.754 T:20844   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 0
17:31:47.756 T:20844   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 1
17:31:47.759 T:664   DEBUG: CAnnouncementManager - Announcement: OnAVStart from xbmc
17:31:47.760 T:664   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnAVStart
17:31:47.766 T:17616   DEBUG:  - DVDNAV_VTS_CHANGE (HOLDING)
17:31:47.767 T:17616  NOTICE: VideoPlayer: next stream, wait for old streams to be finished
17:31:47.767 T:17616  NOTICE: Closing stream player 2
17:31:47.768 T:17616  NOTICE: CDVDMessageQueue(video)::WaitUntilEmpty
17:31:47.779 T:4516   DEBUG: CWinRenderer::CreateIntermediateRenderTarget: format 87.
17:31:47.781 T:4516   DEBUG: ------ Window Deinit (DialogBusy.xml) ------
17:31:47.787 T:664   DEBUG: CAnnouncementManager - Announcement: OnAVChange from xbmc
17:31:47.787 T:664   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnAVChange
17:31:48.007 T:20844  NOTICE: CDVDVideoCodecFFmpeg::CDropControl: calculated diff time: 40949
17:31:48.371 T:4516   DEBUG: Keyboard: scancode: 0x2d, sym: 0x0078, unicode: 0x0078, modifier: 0x0
17:31:48.373 T:4516   DEBUG: CInputManager::HandleKey: x (0xf058) pressed, action is Stop
17:31:48.374 T:4516  NOTICE: CVideoPlayer::CloseFile()
17:31:48.375 T:4516  NOTICE: VideoPlayer: waiting for threads to exit
17:31:48.879 T:20844 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

Stack trace:

>	kodi.exe!XbmcThreads::ConditionVariable::wait(CCriticalSection & lock, unsigned long milliseconds) Zeile 47	C++
 	kodi.exe!XbmcThreads::TightConditionVariable<bool volatile &>::wait<CCriticalSection>(CCriticalSection & lock, unsigned long milliseconds) Zeile 100	C++
 	kodi.exe!CEvent::WaitMSec(unsigned int milliSeconds) Zeile 79	C++
 	kodi.exe!CThread::WaitForThreadExit(unsigned int milliseconds) Zeile 142	C++
 	kodi.exe!CThread::StopThread(bool bWait) Zeile 156	C++
 	kodi.exe!CVideoPlayer::CloseFile(bool reopen) Zeile 754	C++
 	kodi.exe!CApplicationPlayer::CloseFile(bool reopen) Zeile 55	C++
 	kodi.exe!CApplicationPlayer::ClosePlayer() Zeile 39	C++
 	kodi.exe!CApplication::StopPlaying() Zeile 3319	C++
 	kodi.exe!CApplication::OnAction(const CAction & action) Zeile 1788	C++
 	kodi.exe!CInputManager::ExecuteInputAction(const CAction & action) Zeile 688	C++
 	kodi.exe!CInputManager::HandleKey(const CKey & key) Zeile 634	C++
 	kodi.exe!CInputManager::OnKey(const CKey & key) Zeile 473	C++
 	kodi.exe!CInputManager::OnEvent(XBMC_Event & newEvent) Zeile 334	C++
 	kodi.exe!CApplication::HandlePortEvents() Zeile 304	C++
 	kodi.exe!CApplication::FrameMove(bool processEvents, bool processGUI) Zeile 2344	C++
 	kodi.exe!CXBApplicationEx::Run(const CAppParamParser & params) Zeile 68	C++
 	kodi.exe!XBMC_Run(bool renderGUI, const CAppParamParser & params) Zeile 72	C++
 	kodi.exe!WinMain(HINSTANCE__ * hInst, HINSTANCE__ * __formal, char * commandLine, int __formal) Zeile 121	C++

@FernetMenta
Copy link
Contributor

VP::OnExit is not yet called, because of this the subplayers are not notified:

It should get called right after
17:31:48.375 T:4516 NOTICE: VideoPlayer: waiting for threads to exit
because StopThread is called.

Post backtrace of VideoPlayer thread.

@peak3d
Copy link
Contributor Author

peak3d commented Feb 7, 2019

main:

[Externer Code]	
 	[Unten angegebene Rahmen sind möglicherweise nicht korrekt und/oder fehlen, keine Symbole geladen für ntdll.dll]	
>	kodi.exe!XbmcThreads::ConditionVariable::wait(CCriticalSection & lock, unsigned long milliseconds) Zeile 47	C++
 	kodi.exe!XbmcThreads::TightConditionVariable<bool volatile &>::wait<CCriticalSection>(CCriticalSection & lock, unsigned long milliseconds) Zeile 100	C++
 	kodi.exe!CEvent::WaitMSec(unsigned int milliSeconds) Zeile 79	C++
 	kodi.exe!CThread::WaitForThreadExit(unsigned int milliseconds) Zeile 142	C++
 	kodi.exe!CThread::StopThread(bool bWait) Zeile 156	C++
 	kodi.exe!CVideoPlayer::CloseFile(bool reopen) Zeile 754	C++
 	kodi.exe!CApplicationPlayer::CloseFile(bool reopen) Zeile 55	C++
 	kodi.exe!CApplicationPlayer::ClosePlayer() Zeile 39	C++
 	kodi.exe!CApplication::StopPlaying() Zeile 3319	C++
 	kodi.exe!CApplication::OnAction(const CAction & action) Zeile 1788	C++
 	kodi.exe!CInputManager::ExecuteInputAction(const CAction & action) Zeile 688	C++
 	kodi.exe!CInputManager::HandleKey(const CKey & key) Zeile 634	C++
 	kodi.exe!CInputManager::OnKey(const CKey & key) Zeile 473	C++
 	kodi.exe!CInputManager::OnEvent(XBMC_Event & newEvent) Zeile 334	C++
 	kodi.exe!CApplication::HandlePortEvents() Zeile 304	C++
 	kodi.exe!CApplication::FrameMove(bool processEvents, bool processGUI) Zeile 2344	C++
 	kodi.exe!CXBApplicationEx::Run(const CAppParamParser & params) Zeile 68	C++
 	kodi.exe!XBMC_Run(bool renderGUI, const CAppParamParser & params) Zeile 72	C++
 	kodi.exe!WinMain(HINSTANCE__ * hInst, HINSTANCE__ * __formal, char * commandLine, int __formal) Zeile 121	C++

VP:

>	kodi.exe!XbmcThreads::ConditionVariable::wait(CCriticalSection & lock, unsigned long milliseconds) Zeile 47	C++
 	kodi.exe!XbmcThreads::ConditionVariable::wait(CSingleLock & lock, unsigned long milliseconds) Zeile 53	C++
 	kodi.exe!CDVDMsgGeneralSynchronize::Wait(unsigned int milliseconds, unsigned int source) Zeile 62	C++
 	kodi.exe!CDVDMsgGeneralSynchronize::Wait(std::atomic<bool> & abort, unsigned int source) Zeile 80	C++
 	kodi.exe!CDVDMessageQueue::WaitUntilEmpty() Zeile 298	C++
 	kodi.exe!CVideoPlayerVideo::CloseStream(bool bWaitForBuffers) Zeile 234	C++
 	kodi.exe!CVideoPlayer::CloseStream(CCurrentStream & current, bool bWaitForBuffers) Zeile 3898	C++
 	kodi.exe!CVideoPlayer::Process() Zeile 1523	C++
 	kodi.exe!CThread::Action() Zeile 202	C++
 	kodi.exe!CThread::staticThread(void * data) Zeile 119	C++

VPV:

>	kodi.exe!XbmcThreads::ConditionVariable::wait(CCriticalSection & lock, unsigned long milliseconds) Zeile 47	C++
 	kodi.exe!XbmcThreads::ConditionVariable::wait(CSingleLock & lock, unsigned long milliseconds) Zeile 53	C++
 	kodi.exe!CRenderManager::WaitForBuffer(volatile std::atomic<bool> & bStop, int timeout) Zeile 1055	C++
 	kodi.exe!CVideoPlayerVideo::OutputPicture(const VideoPicture * pPicture) Zeile 911	C++
 	kodi.exe!CVideoPlayerVideo::Process() Zeile 348	C++
 	kodi.exe!CThread::Action() Zeile 202	C++
 	kodi.exe!CThread::staticThread(void * data) Zeile 119	C++

@peak3d
Copy link
Contributor Author

peak3d commented Feb 7, 2019

What I don't get clear is why m_bAbortOutput is set to false in CVideoPlayerVideo::OutputPicture.
Once set it wil be resetted if there are one or more frames available (??)

@FernetMenta
Copy link
Contributor

 	kodi.exe!CDVDMessageQueue::WaitUntilEmpty() Zeile 298	C++
 	kodi.exe!CVideoPlayerVideo::CloseStream(bool bWaitForBuffers) Zeile 234	C++

bWaitForBuffers should be false but it seems it is true.

@FernetMenta
Copy link
Contributor

The problem is inputstream->Abort() results into CDVDInputStream::NEXTSTREAM_OPEN

VP hangs here: https://github.com/xbmc/xbmc/blob/master/xbmc/cores/VideoPlayer/VideoPlayer.cpp#L1511

@FernetMenta
Copy link
Contributor

make CDVDInputStreamNavigator::NextStream return NEXTSTREAM_NONE after Abort() was called

@peak3d
Copy link
Contributor Author

peak3d commented Feb 7, 2019

This doesn't help. My keypress is after the Nextstream was selected

Log:

18:27:45.364 T:3220   DEBUG: CVideoPlayerVideo - CDVDMsg::GENERAL_RESYNC(216983.333333)
18:27:45.365 T:3220   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 0
18:27:45.368 T:3220   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 1
18:27:45.373 T:8016   DEBUG: CAnnouncementManager - Announcement: OnAVStart from xbmc
18:27:45.374 T:8016   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnAVStart
18:27:45.376 T:7112   DEBUG:  - DVDNAV_VTS_CHANGE (HOLDING)
18:27:45.376 T:7112  NOTICE: VideoPlayer: next stream, wait for old streams to be finished
18:27:45.377 T:7112  NOTICE: Closing stream player 2
18:27:45.377 T:7112  NOTICE: CDVDMessageQueue(video)::WaitUntilEmpty
18:27:45.392 T:15792   DEBUG: CWinRenderer::CreateIntermediateRenderTarget: format 87.
18:27:45.394 T:15792   DEBUG: ------ Window Deinit (DialogBusy.xml) ------
18:27:45.399 T:8016   DEBUG: CAnnouncementManager - Announcement: OnAVChange from xbmc
18:27:45.400 T:8016   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnAVChange
18:27:45.560 T:15792   DEBUG: Keyboard: scancode: 0x2d, sym: 0x0078, unicode: 0x0078, modifier: 0x0
18:27:45.560 T:15792   DEBUG: CInputManager::HandleKey: x (0xf058) pressed, action is Stop
18:27:45.561 T:15792  NOTICE: CVideoPlayer::CloseFile()
18:27:45.562 T:15792  NOTICE: VideoPlayer: waiting for threads to exit
18:27:46.050 T:3220 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

If your internet bandwith is okish, you can reproduce on every platform with the bugsbunny iso linked above. So, id you still use kodi, you may want to try by yourself?

Simply start the stream, and press x if the first frames get visible

@FernetMenta
Copy link
Contributor

Can't repro here. I downloaded the linked iso. There is no legal notice. I click on start movie, the movie starts. On x it stops immediately.

@peak3d
Copy link
Contributor Author

peak3d commented Feb 7, 2019

Try harder :-) For me the legal notice came only once, after that it was just skipped / not displayed (on both win and android). If your legal notice is visible every time, try to press x as late as possible in the legal notice, Issue does not appear always, but after 3, 4 times I usually get it in this state.

@FernetMenta
Copy link
Contributor

The root cause is that the main thread and render thread are the same. When you hit 'x' for stop the render thread won't render anymore. The best fix is to shut down RM before VP:

diff --git a/xbmc/cores/VideoPlayer/VideoPlayer.cpp b/xbmc/cores/VideoPlayer/VideoPlayer.cpp
--- a/xbmc/cores/VideoPlayer/VideoPlayer.cpp
+++ b/xbmc/cores/VideoPlayer/VideoPlayer.cpp
@@ -742,6 +742,8 @@ bool CVideoPlayer::CloseFile(bool reopen)
   if(m_pInputStream)
     m_pInputStream->Abort();
 
+  m_renderManager.UnInit();
+
   CLog::Log(LOGNOTICE, "VideoPlayer: waiting for threads to exit");
 
   // wait for the main thread to finish up
@@ -758,7 +760,6 @@ bool CVideoPlayer::CloseFile(bool reopen)
   m_HasAudio = false;
 
   CLog::Log(LOGNOTICE, "VideoPlayer: finished waiting");
-  m_renderManager.UnInit();
   return true;
 }
 
diff --git a/xbmc/cores/VideoPlayer/VideoRenderers/RenderManager.cpp b/xbmc/cores/VideoPlayer/VideoRenderers/RenderManager.cpp
--- a/xbmc/cores/VideoPlayer/VideoRenderers/RenderManager.cpp
+++ b/xbmc/cores/VideoPlayer/VideoRenderers/RenderManager.cpp
@@ -399,6 +399,7 @@ void CRenderManager::UnInit()
   m_renderState = STATE_UNCONFIGURED;
   m_width = 0;
   m_height = 0;
+  m_bRenderGUI = false;
   RemoveCaptures();
 
   m_initEvent.Set();

@peak3d peak3d force-pushed the flush branch 2 times, most recently from d5bf100 to 8253050 Compare February 8, 2019 08:34
@iz8mbw
Copy link

iz8mbw commented Feb 11, 2019

Hi @peak3d
Thank you for this commit, now switching between live TV stream and movies is more fast! Still thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Component: Video Type: Improvement non-breaking change which improves existing functionality v18 Leia
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants