[Pending] Slow RTSP startup causes EOF indication (1 Viewer)

dmertz

Portal Member
January 10, 2011
11
2
Home Country
United States of America United States of America
Apparently my server can be a bit slow to begin delivering recorded TV via RTSP at times. When this startup delay exceeds 2000 ticks, it causes TsReader's demuxer to declare a premature EOF condition. This causes MP to further misbehave in that MP fails to play the file while continuing to keep the RTSP stream coming, eventually exceeding the maximum allowed amount of buffering. The fix I'm providing here deals with preventing the false EOF at startup, eliminating this particular trigger of the MP hang. This does not include any changes to improve MP's handling of an RTSP EOF at startup; I've only corrected the false EOF.

CDeMultiplexer.ReadFromFile() declares an EOF if the time since the previous RTSP packet arrived (or, in this case, since the initiation of the RTSP stream) exceeds 2000 ticks. Since CDeMultiplexer.Start() is already capable of making repeated calls to ReadFromFile() to establish an initial amount of buffered data, it makes sense that a premature EOF be ignored. The code change I made simply moves one line of code to cause m_bEndOfFile to be reinitialized to false immediatly prior to each call to ReadFromFile() by Start(). If the final call to ReadFromFile() by Start() results in an EOF indication, the EOF indication remains set.

I've also increased the time allowed by Start() to initially fill the buffer from 5000 ticks to 10000 ticks. This increase normally has no effect since the initial fill should complete prior to that anyway, but the higher value provides a bit more margin since the premature EOF issue shows that the beginning of streaming can be delayed by at least 2000 ticks.

I've attached a set of logs made before the code change that show the EOF indication being prematurely set (TsReader log, demux:endoffile) and the subsequent filling of the buffer to maximum because the data is not being consumed. (Ignore the server logs; the client was actually connecting to a server on a different machine.) TsReader logs made after implementing the code change show that recorded-TV playing proceeds normally despite demux:endof file appearing in the log, and the MP hang is avoided.

The .patch file contains changes to DirectShowFilters\TsReader\DeMultiplexer.cpp.

Dave
 

Attachments

  • slow rtsp startup fix.patch
    905 bytes
Last edited by a moderator:

sincze

Portal Pro
September 18, 2011
76
1
99
Is this problem still there in MP 1.2.
It seems I have the same problem

Log:
22-09-2011 20:51:46.025 [1dec]---------- v0.4.12 -------------------
22-09-2011 20:51:46.026 [1dec]CTsReaderFilter::ctor
22-09-2011 20:51:46.026 [1dec]CRTSPClient::Initialize()
22-09-2011 20:51:46.026 [1dec]CRTSPClient::createClient()
22-09-2011 20:51:46.027 [1dec]Slow motion video allowed during zapping
22-09-2011 20:51:46.027 [1dec]Wait for seeking to eof - false - constructor
22-09-2011 20:51:46.027 [1dec]SetRelaxedMode
22-09-2011 20:51:46.028 [1dec]Normal discontinuities filtering
22-09-2011 20:51:46.028 [1dec]CALLBACK SET
22-09-2011 20:51:46.028 [1dec]SetRequestAudioChangeCallback SET
22-09-2011 20:51:46.029 [1dec]CTsReaderFilter::Load()
22-09-2011 20:51:46.029 [1dec]open rtsp:rtsp://media-PC:554/2E39FE57
22-09-2011 20:51:46.029 [1dec]CRTSPClient::OpenStream()
22-09-2011 20:51:46.029 [1dec]CRTSPClient::getSDPDescriptionFromURL()
22-09-2011 20:51:46.194 [1dec]rangestart:0.000000 rangeend:4017.769000
22-09-2011 20:51:46.196 [1dec]Created receiver for video MP2T 55142 55143
22-09-2011 20:51:46.196 [1dec]rtsp:increaseReceiveBufferTo to 2000000 for s:1824
22-09-2011 20:51:46.197 [1dec]CRTSPClient::setupStreams()
22-09-2011 20:51:46.197 [1dec]CRTSPClient::clientSetupSubsession()
22-09-2011 20:51:46.201 [1dec]Setup video MP2T 55142 55143
22-09-2011 20:51:46.202 [1dec]CMemorySink::ctor
22-09-2011 20:51:46.202 [1dec]Created output sink:
22-09-2011 20:51:46.202 [1dec]memorybuffer: Clear() 0
22-09-2011 20:51:46.203 [1dec]memorybuffer: Clear() done
22-09-2011 20:51:46.203 [1dec]memorybuffer: run:1 1
22-09-2011 20:51:46.203 [1dec]memorybuffer: running:1
22-09-2011 20:51:46.203 [1dec]CRTSPClient::play from 0.000000 / 0.000000
22-09-2011 20:51:46.204 [1dec]CRTSPClient::startPlayingStreams()
22-09-2011 20:51:46.204 [1dec]CRTSPClient::clientStartPlayingSession()
22-09-2011 20:51:46.204 [1dec]CRTSPClient::clientStartPlayingSession() play from 0.000 / 4017.769
22-09-2011 20:51:46.216 [1dec]Started playing session
22-09-2011 20:51:46.217 [1dec]CRTSPClient::confused:tartBufferThread
22-09-2011 20:51:46.217 [1dec]CRTSPClient::confused:tartBufferThread done
22-09-2011 20:51:46.218 [2674]CRTSPClient:: thread started:9844
22-09-2011 20:51:48.037 [1dec]demux:endoffile
22-09-2011 20:51:48.047 [1dec]demux:endoffile
22-09-2011 20:51:48.057 [1dec]demux:endoffile
22-09-2011 20:51:48.067 [1dec]demux:endoffile
2-09-2011 20:51:51.211 [1dec]demux:endoffile
22-09-2011 20:51:51.221 [1dec]memorybuffer: run:0 1
22-09-2011 20:51:51.221 [1dec]memorybuffer: Clear() 0
22-09-2011 20:51:51.221 [1dec]memorybuffer: Clear() done
22-09-2011 20:51:51.221 [1dec]memorybuffer: running:0
22-09-2011 20:51:51.222 [1dec]close rtsp:rtsp://media-PC:554/2E39FE57
22-09-2011 20:51:51.222 [1dec]CRTSPClient:confused:top
22-09-2011 20:51:51.222 [1dec]CRTSPClient::confused:topBufferThread
22-09-2011 20:51:51.297 [2674]CRTSPClient:: thread stopped:9844
22-09-2011 20:51:51.297 [1dec]CRTSPClient::confused:topBufferThread done
22-09-2011 20:51:51.298 [1dec]CRTSPClient::shutdown()
22-09-2011 20:51:51.298 [1dec]CRTSPClient::closeMediaSinks()
22-09-2011 20:51:51.298 [1dec]CMemorySink::dtor
22-09-2011 20:51:51.298 [1dec]CRTSPClient::tearDownStreams()
22-09-2011 20:51:51.299 [1dec]CRTSPClient::clientTearDownSession()
22-09-2011 20:51:51.306 [1dec]memorybuffer: Clear() 0
22-09-2011 20:51:51.307 [1dec]memorybuffer: Clear() done
22-09-2011 20:51:51.307 [1dec]CRTSPClient:confused:top done
22-09-2011 20:51:52.361 [1dec]aud:CompleteConnect()
22-09-2011 20:51:52.362 [1dec]aud:CompleteConnect() done
22-09-2011 20:51:52.436 [1dec]CTsReaderFilter::pause() - IsTimeShifting = 0 - state = 0
22-09-2011 20:51:52.437 [1dec] -- Pause() ->start rtsp from 0.000000
22-09-2011 20:51:52.437 [1744]aud:OnThreadStartPlay(0.000000) 1.00
22-09-2011 20:51:52.437 [1dec]memorybuffer: Clear() 0
22-09-2011 20:51:52.437 [1744]aud:set eof
22-09-2011 20:51:52.438 [1dec]memorybuffer: Clear() done
22-09-2011 20:51:52.438 [1dec]demux:flushing
22-09-2011 20:51:52.438 [1dec]demux:set hold audio:1
22-09-2011 20:51:52.438 [1dec]demux:set hold video:1
22-09-2011 20:51:52.439 [1dec]demux:set hold subtitle:1
22-09-2011 20:51:52.439 [1dec]demux:flush audio
22-09-2011 20:51:52.439 [1dec]demux:flush video
22-09-2011 20:51:52.439 [1dec]demux:flush subtitle
22-09-2011 20:51:52.439 [1dec]demux:set hold audio:0
22-09-2011 20:51:52.439 [1dec]demux:set hold video:0
22-09-2011 20:51:52.440 [1dec]demux:set hold subtitle:0
22-09-2011 20:51:52.440 [1dec]memorybuffer: run:1 0
22-09-2011 20:51:52.440 [1dec]memorybuffer: running:1
22-09-2011 20:51:52.440 [1dec]CRTSPClient::play from 0.000000 / 0.000000
22-09-2011 20:51:52.440 [1dec]memorybuffer: Clear() 0
22-09-2011 20:51:52.440 [1dec]memorybuffer: Clear() done
22-09-2011 20:51:52.441 [1dec]CRTSPClient::Initialize()
22-09-2011 20:51:52.441 [1dec]CRTSPClient::createClient()
22-09-2011 20:51:52.441 [1dec]CRTSPClient::OpenStream()
22-09-2011 20:51:52.441 [1dec]CRTSPClient::getSDPDescriptionFromURL()
22-09-2011 20:51:52.465 [1dec]rangestart:0.000000 rangeend:4017.769000
22-09-2011 20:51:52.466 [1dec]Created receiver for video MP2T 50192 50193
22-09-2011 20:51:52.466 [1dec]rtsp:increaseReceiveBufferTo to 2000000 for s:2192
22-09-2011 20:51:52.466 [1dec]CRTSPClient::setupStreams()
22-09-2011 20:51:52.466 [1dec]CRTSPClient::clientSetupSubsession()
22-09-2011 20:51:52.470 [1dec]Setup video MP2T 50192 50193
22-09-2011 20:51:52.471 [1dec]CMemorySink::ctor
22-09-2011 20:51:52.471 [1dec]Created output sink:
22-09-2011 20:51:52.471 [1dec]CRTSPClient::startPlayingStreams()
22-09-2011 20:51:52.471 [1dec]CRTSPClient::clientStartPlayingSession()
22-09-2011 20:51:52.471 [1dec]CRTSPClient::clientStartPlayingSession() play from 0.000 / 4017.769
22-09-2011 20:51:52.474 [1dec]Started playing session
22-09-2011 20:51:52.475 [1dec]CRTSPClient::confused:tartBufferThread
22-09-2011 20:51:52.475 [1dec]CRTSPClient::confused:tartBufferThread done
22-09-2011 20:51:52.476 [1dec] -- Pause() ->rtsp started
22-09-2011 20:51:52.476 [1dec]Timeshift 0, Recording 1, StartPCR 0.000000, EndPcr 4017.769000, Duration 4017.768000
22-09-2011 20:51:52.476 [1ccc]CRTSPClient:: thread started:7372
22-09-2011 20:51:52.476 [1dec]CTsReaderFilter::pause() - END - state = 1
22-09-2011 20:51:52.477 [219c]CTsReaderFilter::ThreadProc start()
22-09-2011 20:51:52.477 [219c]CTsReaderFilter::ThreadProc stopped()
22-09-2011 20:51:52.478 [1dec]filt:IID_IMediaSeeking()
22-09-2011 20:51:52.478 [1dec]CTsReaderFilter::Run(251921.58) state 1 seeking 0
22-09-2011 20:51:52.478 [1dec]CTsReaderFilter::Run(251921.58) state 2 -->done
22-09-2011 20:51:52.492 [1dec]SetAudioStream : 0
22-09-2011 20:51:52.495 [1dec]SetAudioStream : 0
22-09-2011 20:51:52.586 [1dec]CTsReaderFilter::pause() - IsTimeShifting = 0 - state = 2
22-09-2011 20:51:52.587 [1dec] -- Pause() ->pause rtsp at position: 783402.034000
22-09-2011 20:51:52.587 [1dec]CRTSPClient::pause()
22-09-2011 20:51:52.587 [1dec]CRTSPClient::pause() stopthread
22-09-2011 20:51:57.554 [1ccc]CRTSPClient:: thread stopped:7372
22-09-2011 20:51:57.554 [1dec]CRTSPClient::pause() thread stopped
22-09-2011 20:51:57.557 [1dec]CRTSPClient::pause() done
22-09-2011 20:51:57.557 [1dec]CTsReaderFilter::pause() - END - state = 1
22-09-2011 20:51:57.558 [2164]CTsReaderFilter::ThreadProc start()
22-09-2011 20:51:57.558 [2164]CTsReaderFilter::ThreadProc stopped()
22-09-2011 20:51:57.563 [1dec]CTsReaderFilter::confused:top()
22-09-2011 20:51:57.563 [1dec]CTsReaderFilter::confused:top() -stop source
22-09-2011 20:51:57.564 [1dec]CTsReaderFilter::confused:top() -stop source done
22-09-2011 20:51:57.564 [1dec]CTsReaderFilter::confused:top() -- stop rtsp
22-09-2011 20:51:57.564 [1dec]memorybuffer: run:0 1
22-09-2011 20:51:57.565 [1dec]memorybuffer: Clear() 0
22-09-2011 20:51:57.565 [1dec]memorybuffer: Clear() done
22-09-2011 20:51:57.565 [1dec]memorybuffer: running:0
22-09-2011 20:51:57.566 [1dec]CRTSPClient:confused:top
22-09-2011 20:51:57.566 [1dec]CRTSPClient::shutdown()
22-09-2011 20:51:57.566 [1dec]CRTSPClient::closeMediaSinks()
22-09-2011 20:51:57.567 [1dec]CMemorySink::dtor
22-09-2011 20:51:57.567 [1dec]CRTSPClient::tearDownStreams()
22-09-2011 20:51:57.567 [1dec]CRTSPClient::clientTearDownSession()
22-09-2011 20:51:57.576 [1dec]memorybuffer: Clear() 0
22-09-2011 20:51:57.576 [1dec]memorybuffer: Clear() done
22-09-2011 20:51:57.576 [1dec]CRTSPClient:confused:top done
22-09-2011 20:51:57.577 [1dec]CTsReaderFilter::confused:top() done
22-09-2011 20:51:58.127 [1dec]CTsReaderFilter::dtor
22-09-2011 20:51:58.127 [1dec]pin:dtor()
22-09-2011 20:51:58.127 [1dec]sub pin:dtor()
22-09-2011 20:51:58.128 [1dec]FileReader::CloseFile() no open file
22-09-2011 20:51:58.128 [1dec]CMemoryBuffer::dtor
22-09-2011 20:51:58.128 [1dec]memorybuffer: Clear() 0
22-09-2011 20:51:58.128 [1dec]memorybuffer: Clear() done
22-09-2011 20:51:58.129 [1dec]CRTSPClient::~CRTSPClient()
22-09-2011 20:51:58.129 [1dec]demux:flushing
22-09-2011 20:51:58.129 [1dec]demux:set hold audio:1
22-09-2011 20:51:58.130 [1dec]demux:set hold video:1
22-09-2011 20:51:58.130 [1dec]demux:set hold subtitle:1
22-09-2011 20:51:58.130 [1dec]demux:flush audio
22-09-2011 20:51:58.130 [1dec]demux:flush video
22-09-2011 20:51:58.131 [1dec]demux:flush subtitle
22-09-2011 20:51:58.131 [1dec]demux:set hold audio:0
22-09-2011 20:51:58.131 [1dec]demux:set hold video:0
22-09-2011 20:51:58.131 [1dec]demux:set hold subtitle:0
 

glenn 1990

Portal Pro
July 1, 2010
247
36
Home Country
Belgium Belgium
Can this be added to the trunk??

This is the only way to get rtsp working with my powerlan (low bandwidth) client.
Now the powerlan adapters are getting more popular, more people will face against this problem.
 

sincze

Portal Pro
September 18, 2011
76
1
99
I'll build a version of the 1.2.1 TsReader.ax soon with the patch included so people can test it

Great. Put me on your beta-testers list. ;-0
Still my wireless connection speed is 100 mbit, the other machine is connected wired to my ubee router at 1 gigabit.
 

Owlsroost

Retired Team Member
  • Premium Supporter
  • October 28, 2008
    5,540
    5,038
    Cambridge
    Home Country
    United Kingdom United Kingdom
    I'll build a version of the 1.2.1 TsReader.ax soon with the patch included so people can test it.

    Tony

    OK, here it is :)

    Because it's easier for me, it also includes the 'graph rebuild on zapping' mod which has been around for a while.

    I can't easily test the RTSP stuff, so it's in your hands.... ;)

    EDIT: Binary removed - see https://forum.team-mediaportal.com/submit-code-patches-mediaportal-tv-server-etc-325/slow-rtsp-startup-causes-eof-indication-96460/index2.html#post801539

    Tony
     

    Owlsroost

    Retired Team Member
  • Premium Supporter
  • October 28, 2008
    5,540
    5,038
    Cambridge
    Home Country
    United Kingdom United Kingdom
    Would graph rebuild on zapping do anything for those that do not use RTSP?

    Yes, mostly in situations where the video frame size changes but the video/audio type doesn't - some video codecs break in this situation. The mod has been around in various test versions for a while, but it was too late to include it in 1.2.0 - it's likely to go into 1.2.2

    Tony
     

    disaster123

    MP Donator
  • Premium Supporter
  • May 14, 2008
    3,558
    434
    Home Country
    Germany Germany
    AW: Slow RTSP startup causes EOF indication

    @Owlroost
    i can't finde that patch (graph rebuild) in the patch submission forum?
     

    Users who are viewing this thread

    Top Bottom