Huge delay from channel selection to viewing

Discussion in 'Television (MyTV frontend and TV-Server)' started by porky996t, January 8, 2017.

  1. porky996t
    • Premium Supporter

    porky996t MP Donator

    Joined:
    May 21, 2008
    Messages:
    1,013
    Likes Received:
    75
    Gender:
    Male
    Occupation:
    Chartered Surveyor
    Location:
    Bolton, Lancashire, England
    Ratings:
    +82 / 0
    Home Country:
    England England
    Show System Specs
    Hi Guys,

    I have recently started to experience a large time delay between choosing a live TV channel and the picture and audio being 'received' by the client.

    It usually happens on first start up of a client (the server runs permanently), and once the stream is being received, any subsequent channel change generally takes about 5 seconds.



    I have tried on all 4 clients that are on ethernet cabling and it is the same situation, so obviously a server/timeshifting issue.

    Find attached logs. At 12:03 I tuned to Channel 4 HD from my workstation PC, and then after about 35-38 seconds the picture was then received. About 12:05 I stopped the live TV stream on the workstation PC.

    Any suggestions welcomed as I'm getting a bit of pain from the GF (she is soooo impatient!) :censored::love:

    Thanks in advance.
     
  2. Google AdSense Guest Advertisement



    to hide all adverts.
  3. Owlsroost
    • Team MediaPortal

    Owlsroost Development Group

    Joined:
    October 28, 2008
    Messages:
    5,536
    Likes Received:
    2,828
    Location:
    Cambridge
    Ratings:
    +4,130 / 1
    Home Country:
    United Kingdom United Kingdom
    Show System Specs
    So what has changed recently on the server (or in the networking hardware) ?

    There is no big delay showing up when tuning/starting to write to timeshift buffer files, but there is in the StreamServer (RTSP) log, so we need the client logs as well to get the full picture.

    TV service log:
    [2017-01-08 12:03:36,120] [Log ] [8 ] [INFO ] - Controller: find free card for channel Channel 4 HD
    [2017-01-08 12:03:36,120] [Log ] [8 ] [INFO ] - Controller: find card for channel Channel 4 HD
    [2017-01-08 12:03:36,120] [Log ] [8 ] [INFO ] - Controller: got 2 tuning details for Channel 4 HD
    [2017-01-08 12:03:36,120] [Log ] [8 ] [INFO ] - Controller: channel #1 DVBT:tv: Channel 4 HD Freq:738000 ONID:9018 TSID:16520 SID:17664 PMT:0x12C FTA:True LCN:104 BandWidth:8

    TsWriter log:
    [2017-01-08 12:03:38,913] [4695500] [cbc] - Recorder: TIMESHIFT Start 'Z:\Timeshift\live3-0.ts.tsbuffer'
    [2017-01-08 12:03:38,928] [4695500] [d54] - Recorder: TIMESHIFT start of audio detected
    [2017-01-08 12:03:39,022] [4695500] [d54] - Recorder: TIMESHIFT start of video detected
    [2017-01-08 12:03:39,038] [4695500] [d54] - Recorder: TIMESHIFT clear TS packet queue
    [2017-01-08 12:03:39,038] [4695500] [d54] - CDiskRecorder::WriteToTimeshiftFile() - Reset write buffer throttle
    [2017-01-08 12:03:39,038] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 376 bytes
    [2017-01-08 12:03:39,038] [4695500] [d54] - Recorder: TIMESHIFT Info : Next broadcaster program clock reference rollover : 1 days 00:18:38 0
    [2017-01-08 12:03:39,038] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 564 bytes
    [2017-01-08 12:03:39,038] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 940 bytes
    [2017-01-08 12:03:39,038] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 940 bytes
    [2017-01-08 12:03:39,038] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 940 bytes
    [2017-01-08 12:03:39,038] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 940 bytes
    [2017-01-08 12:03:39,053] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 940 bytes
    [2017-01-08 12:03:39,053] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 1880 bytes
    [2017-01-08 12:03:39,053] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 1880 bytes
    [2017-01-08 12:03:39,053] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 1880 bytes
    [2017-01-08 12:03:39,053] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 1880 bytes
    [2017-01-08 12:03:39,053] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 1880 bytes
    [2017-01-08 12:03:39,069] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 3760 bytes
    [2017-01-08 12:03:39,069] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 3760 bytes
    [2017-01-08 12:03:39,069] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 3760 bytes
    [2017-01-08 12:03:39,084] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 6016 bytes
    [2017-01-08 12:03:39,084] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 7520 bytes
    [2017-01-08 12:03:39,100] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 9400 bytes
    [2017-01-08 12:03:39,116] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 15416 bytes
    [2017-01-08 12:03:39,162] [4695500] [d54] - CDiskRecorder::Flush() - Throttle to 32336 bytes (max)

    StreamingServer log (with long delay):

    08-01-2017 12:03:39.22 Stream server: add timeshift mpeg-2 transport stream stream3.0 filename:Z:\Timeshift\live3-0.ts.tsbuffer
    08-01-2017 12:03:39.22 Stream server: url for stream is rtsp://192.168.1.10/stream3.0
    08-01-2017 12:04:22.764 ts:eek:pen Z:\Timeshift\live3-0.ts.tsbuffer <- Note 43s delay from previous line
    08-01-2017 12:04:22.764 ts:ctor:5c4bd8
    08-01-2017 12:04:22.764 CTSBuffer::confused:etChannelType() - Buffer size set to TV (32336)
    08-01-2017 12:04:22.764 ts:size 28552688
    08-01-2017 12:04:22.764 ts:dtor:5c4bd8
    08-01-2017 12:04:22.764 generateSDPDescription() duration 43.679001 : a=range:npt=0-43.679
     
  4. porky996t
    • Premium Supporter

    porky996t MP Donator

    Joined:
    May 21, 2008
    Messages:
    1,013
    Likes Received:
    75
    Gender:
    Male
    Occupation:
    Chartered Surveyor
    Location:
    Bolton, Lancashire, England
    Ratings:
    +82 / 0
    Home Country:
    England England
    Show System Specs
    Thanks for the quick response Owlsroost.

    This has been going on for a few months now, hence the GF giving me grief over it. Nothing has changed on the system, no hardware changes, no router changes. I have been doing my annual bit of housekeeping and thought I would try to resolve it to ease my ears.

    On these logs, I tuned to Ch 4 HD at 18:03, the same delay with the picture and when the picture appeared I ran the show for around a minute and then stopped the live TV timeshifting and closed MP down.

    Client logs from Workstation attached..
     
  5. Owlsroost
    • Team MediaPortal

    Owlsroost Development Group

    Joined:
    October 28, 2008
    Messages:
    5,536
    Likes Received:
    2,828
    Location:
    Cambridge
    Ratings:
    +4,130 / 1
    Home Country:
    United Kingdom United Kingdom
    Show System Specs
    The MediaPortal.log starts at 18:02 - need the earlier log file that covers the 12:xx period... (TsReader.log is OK)

    But note that in TsReader.log, TsReader is initialised by the client at 12:04:24 (40+ seconds after TV server starts timeshifting)):

    [2017-01-08 12:04:24,740] [ 0] [ 580] - CTsDuration - ctor
    [2017-01-08 12:04:24,740] [ 0] [ 580] - CTsDuration - ctor
    [2017-01-08 12:04:24,740] [ 0] [ 580] -
    [2017-01-08 12:04:24,740] [ 0] [ 580] - =================== New filter instance ===========================
    [2017-01-08 12:04:24,740] [ 0] [ 580] - Logging format: [Date Time] [InstanceID] [ThreadID] Message....
    [2017-01-08 12:04:24,740] [ 0] [ 580] - ===================================================================
    [2017-01-08 12:04:24,740] [ 0] [ 580] - demux: Start file read thread
    [2017-01-08 12:04:24,740] [ 0] [ 580] - CRTSPClient::CRTSPClient()
    [2017-01-08 12:04:24,740] [ 0] [ 580] - CMemoryBuffer::ctor
    [2017-01-08 12:04:24,740] [2475e7d8] [ 580] - ------------- v4.0.0.0 -------------
    [2017-01-08 12:04:24,740] [2475e7d8] [ 580] - CTsReaderFilter::ctor
    [2017-01-08 12:04:24,740] [2475e7d8] [ 580] - CRTSPClient::Initialize()
    [2017-01-08 12:04:24,740] [2475e7d8] [ 580] - CRTSPClient::createClient()
    [2017-01-08 12:04:24,740] [2475e7d8] [ 580] - ----- UseFPSfromDTSPTS -----
    [2017-01-08 12:04:24,740] [2475e7d8] [ 580] - --- Buffering delay = 0 ms
    [2017-01-08 12:04:24,740] [2475e7d8] [ 580] - --- Audio delay = 0 ms
    [2017-01-08 12:04:24,740] [2475e7d8] [ 558] - CDeMultiplexer::ThreadProc start(), threadID:0x558
    [2017-01-08 12:04:24,740] [2475e7d8] [ 580] - Slow motion video allowed during zapping
    [2017-01-08 12:04:24,740] [2475e7d8] [ 580] - Wait for seeking to eof - false - constructor
    [2017-01-08 12:04:24,740] [2475e7d8] [ 580] - CTsReaderFilter::confused:tart duration thread
    [2017-01-08 12:04:24,740] [2475e7d8] [ 580] - CTsReaderFilter::timeGetTime():0x927c2e, m_tGTStartTime:0xc0927c2e, GET_TIME_NOW:0x40000000
    [2017-01-08 12:04:24,740] [2475e7d8] [ 9e0] - CTsReaderFilter::ThreadProc start(), threadID:0x9e0
    [2017-01-08 12:04:24,840] [2475e7d8] [ 580] - SetRelaxedMode
    [2017-01-08 12:04:24,840] [2475e7d8] [ 580] - Relaxed discontinuities filtering
    [2017-01-08 12:04:24,841] [2475e7d8] [ 580] - CALLBACK SET
    [2017-01-08 12:04:24,841] [2475e7d8] [ 580] - SetRequestAudioChangeCallback SET
    [2017-01-08 12:04:24,841] [2475e7d8] [ 580] - CTsReaderFilter::Load()
    [2017-01-08 12:04:24,841] [2475e7d8] [ 580] - open rtsp:rtsp://192.168.1.10:554/stream3.0
    [2017-01-08 12:04:24,841] [2475e7d8] [ 580] - CRTSPClient::OpenStream()
    [2017-01-08 12:04:24,841] [2475e7d8] [ 580] - CRTSPClient::getSDPDescriptionFromURL()
    [2017-01-08 12:04:24,848] [2475e7d8] [ 580] - rangestart:0.000000 rangeend:43.679000
    [2017-01-08 12:04:24,849] [2475e7d8] [ 580] - Created receiver for video MP2T 59264 59265
    [2017-01-08 12:04:24,849] [2475e7d8] [ 580] - rtsp:increaseReceiveBufferTo to 2000000 for s:5228
    [2017-01-08 12:04:24,849] [2475e7d8] [ 580] - CRTSPClient::setupStreams()
    [2017-01-08 12:04:24,849] [2475e7d8] [ 580] - CRTSPClient::clientSetupSubsession()
    [2017-01-08 12:04:24,851] [2475e7d8] [ 580] - Setup video MP2T 59264 59265
     
  6. Owlsroost
    • Team MediaPortal

    Owlsroost Development Group

    Joined:
    October 28, 2008
    Messages:
    5,536
    Likes Received:
    2,828
    Location:
    Cambridge
    Ratings:
    +4,130 / 1
    Home Country:
    United Kingdom United Kingdom
    Show System Specs
    ...also please use the MP log collector (WatchDog) tool for collecting the client logs - it makes sure we get all the logs...
     
  7. porky996t
    • Premium Supporter

    porky996t MP Donator

    Joined:
    May 21, 2008
    Messages:
    1,013
    Likes Received:
    75
    Gender:
    Male
    Occupation:
    Chartered Surveyor
    Location:
    Bolton, Lancashire, England
    Ratings:
    +82 / 0
    Home Country:
    England England
    Show System Specs
    Thank for the quick response @Owlsroost

    Find attached the 'matching' TSreader.log file from the client machine which I used to when I attached the earlier logs from the server.

    If you need a revised set of logs, let me know and I'll get some attached.
     
  8. Owlsroost
    • Team MediaPortal

    Owlsroost Development Group

    Joined:
    October 28, 2008
    Messages:
    5,536
    Likes Received:
    2,828
    Location:
    Cambridge
    Ratings:
    +4,130 / 1
    Home Country:
    United Kingdom United Kingdom
    Show System Specs
    It was the earlier MediaPortal.log I wanted i.e. the one that covers the 2017-01-08, 12:xx time period (the MP logging keeps the 5 most recent log files, so you may still have the file).

    Otherwise a new complete server and client log set (for when the problem happened) would be the best thing.
     
Loading...

Users Viewing Thread (Users: 0, Guests: 0)

  1. This site uses cookies to help personalise content, tailor your experience and to keep you logged in if you register.
    By continuing to use this site, you are consenting to our use of cookies.
    Dismiss Notice
  • About The Project

    The vision of the MediaPortal project is to create a free open source media centre application, which supports all advanced media centre functions, and is accessible to all Windows users.

    In reaching this goal we are working every day to make sure our software is one of the best.

             

  • Support MediaPortal!

    The team works very hard to make sure the community is running the best HTPC-software. We give away MediaPortal for free but hosting and software is not for us.

    Care to support our work with a few bucks? We'd really appreciate it!