Huge delay from channel selection to viewing (1 Viewer)

porky996t

MP Donator
  • Premium Supporter
  • May 21, 2008
    1,016
    81
    Bolton, Lancashire, England
    Home Country
    England England
    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.
     

    Owlsroost

    Retired Team Member
  • Premium Supporter
  • October 28, 2008
    5,540
    5,038
    Cambridge
    Home Country
    United Kingdom United Kingdom
    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.

    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
     

    porky996t

    MP Donator
  • Premium Supporter
  • May 21, 2008
    1,016
    81
    Bolton, Lancashire, England
    Home Country
    England England
    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..
     

    Owlsroost

    Retired Team Member
  • Premium Supporter
  • October 28, 2008
    5,540
    5,038
    Cambridge
    Home Country
    United Kingdom United Kingdom
    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
     

    Owlsroost

    Retired Team Member
  • Premium Supporter
  • October 28, 2008
    5,540
    5,038
    Cambridge
    Home Country
    United Kingdom United Kingdom
    ...also please use the MP log collector (WatchDog) tool for collecting the client logs - it makes sure we get all the logs...
     

    porky996t

    MP Donator
  • Premium Supporter
  • May 21, 2008
    1,016
    81
    Bolton, Lancashire, England
    Home Country
    England England
    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.
     

    Owlsroost

    Retired Team Member
  • Premium Supporter
  • October 28, 2008
    5,540
    5,038
    Cambridge
    Home Country
    United Kingdom United Kingdom
    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.
     

    Users who are viewing this thread

    Top Bottom