TV always starts delayed on one client (1 Viewer)

[Marcus Venturi]

Everytime I wake up the living room client from standby and start TV the sound starts, but there is no picture. Then after 30 seconds the picture appears. I tried to solve this problem for months, but had no luck yet. Turning off IPV6 didn't change anything. On my dev PC there is no delay when starting TV and as both clients use the same server, I assume it must be a problem with the client.

As the problem was reproducible with the "Report a Bug..." feature in the watchdog I collected some logs and hope that somebody could help me...

 

[mm1352000]

The delay isn't obvious in the log files. I can only guess that this might be it:
[2016-12-18 18:10:09,252] [Log ] [28 ] [DEBUG] - PlaneScene: PresentImage() dispose surfaces
[2016-12-18 18:10:19,616] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [DEBUG] - RemoteControl: TCP connect took : 2
[2016-12-18 18:10:19,616] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-18 18:10:20,619] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-18 18:10:21,622] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-18 18:10:22,625] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-18 18:10:23,628] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-18 18:10:27,549] [Log ] [MPMain ] [WARN ] - tvhome:startplay. Phase 2 - 19526 ms - Done starting g_Player.Play()

...and if you've properly disabled IPv6 (may need to be done on both client and server), I have no idea what might be causing it.
More log files might help to confirm the pattern.

 

[Marcus Venturi]

The delay isn't obvious in the log files. I can only guess that this might be it:
[2016-12-18 18:10:09,252] [Log ] [28 ] [DEBUG] - PlaneScene: PresentImage() dispose surfaces
[2016-12-18 18:10:19,616] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [DEBUG] - RemoteControl: TCP connect took : 2
[2016-12-18 18:10:19,616] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-18 18:10:20,619] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-18 18:10:21,622] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-18 18:10:22,625] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-18 18:10:23,628] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-18 18:10:27,549] [Log ] [MPMain ] [WARN ] - tvhome:startplay. Phase 2 - 19526 ms - Done starting g_Player.Play()

...and if you've properly disabled IPv6 (may need to be done on both client and server), I have no idea what might be causing it.

IPV6 is disabled on the server and the clients. The strange thing is that the sound immediately starts whereas the picture has this delay.
Yesterday I installed a new graphics card (NVIDIA GTX 1050 low profile for more speed in Emulators). The small hope that this might help to solve the problem - if it is related to the graphics - didn't fulfill.

More log files might help to confirm the pattern.

Not clear to me. Do you need additional files (if yes, which ones) or should I repeat the same thing again and provide further logfiles with the "Report a Bug..." feature?

 

[mm1352000]

Not clear to me. Do you need additional files (if yes, which ones)...

No.

...or should I repeat the same thing again and provide further logfiles with the "Report a Bug..." feature?

Yes, please.

 

[mm1352000]

Having said that...

You could also provide the server log files for me to check. There's a possibility that the delay is related to decryption, and the streaming server is waiting until the stream is decrypted. If you do this, please provide both client and server log files together.

Another idea would be to try UNC paths (SMB shares) instead of RTSP:
http://wiki.team-mediaportal.com/1_...ation/22_TV/Advanced_Options#Multi-seat_setup

I don't expect this to solve the problem, but at least I would be able to see whether the delay is related to decryption with only the client log files.

 

[Owlsroost]

According to the TsReader log:

[2016-12-18 18:10:09,138] [144f6850] [13fc] - Run() - Elapsed time from pause to Audio/Video ( total zapping time ) : 1107 mS
[2016-12-18 18:10:09,138] [144f6850] [13fc] - CTsReaderFilter::Run(410509.45) state 2 -->done
[2016-12-18 18:10:09,139] [144f6850] [1e34] - audPin: Add pmt and set discontinuity L:1 B:0 fTime:0.292 SampCnt:0
[2016-12-18 18:10:09,139] [144f6850] [1e34] - Aud/Ref : 0.212, Compensated = 0.293 ( 0.292 A/V buffers=03/24), Clk : 0.001000, SampCnt 0, Sleep 1 ms, stallPt 1.100
[2016-12-18 18:10:09,144] [144f6850] [1e34] - Aud/Ref : 0.332, Compensated = 0.413 ( 0.407 A/V buffers=02/24), Clk : 0.006000, SampCnt 1, Sleep 1 ms, stallPt 1.100
[2016-12-18 18:10:09,148] [144f6850] [1e34] - Aud/Ref : 0.452, Compensated = 0.533 ( 0.523 A/V buffers=01/24), Clk : 0.010000, SampCnt 2, Sleep 1 ms, stallPt 1.100
[2016-12-18 18:10:09,179] [144f6850] [1aa4] - Vid/Ref : 0.679, ?-frame(00), Compensated = 0.390 ( 0.359 A/V buffers=00/24), Clk : 0.031000, SampCnt 1, stallPt 2.500
[2016-12-18 18:10:09,181] [144f6850] [ bcc] - Demux : Video to render 1.207 Sec
[2016-12-18 18:10:09,206] [144f6850] [ bcc] - Demux : Video to render 1.141 Sec
[2016-12-18 18:10:09,214] [144f6850] [1aa4] - Vid/Ref : 0.639, ?-frame(00), Compensated = 0.330 ( 0.263 A/V buffers=00/27), Clk : 0.067000, SampCnt 2, stallPt 2.500
[2016-12-18 18:10:09,216] [144f6850] [1aa4] - Vid/Ref : 0.619, ?-frame(00), Compensated = 0.300 ( 0.231 A/V buffers=00/26), Clk : 0.069000, SampCnt 3, stallPt 2.500
[2016-12-18 18:10:09,255] [144f6850] [ bcc] - Demux : Audio to render 0.546 Sec
[2016-12-18 18:10:09,359] [144f6850] [ bcc] -   H.264 2nd GOP found 1.259000
[2016-12-18 18:10:09,359] [144f6850] [ bcc] - Demux : Video to render 1.129 Sec
[2016-12-18 18:10:09,440] [144f6850] [ bcc] - Demux : Video to render 1.087 Sec
[2016-12-18 18:10:09,492] [144f6850] [ bcc] - Demux : Audio to render 0.544 Sec

...and EVR log it's getting video quite early:

[2016-12-18 18:10:09,254] [14591c50] [1aa4] - ProcessMessage MFVP_MESSAGE_PROCESSINPUTNOTIFY
[2016-12-18 18:10:09,255] [14591c50] [1794] - Adding first sample to empty queue
[2016-12-18 18:10:09,255] [14591c50] [1c80] - Present first sample - start
[2016-12-18 18:10:09,255] [14591c50] [1c80] - Present first sample - end

...so it does look like MP is not switching over to using video samples from EVR presenter until much later i.e. it's staying on the GUI (main thread waiting for/being blocked by something maybe?). The audio part of the playback graph connects directly to the audio renderer (the output doesn't go via MP code) so it starts playing immediately.

 

[Marcus Venturi]

@mm1352000 :
Happened again this morning (see logfiles after 07:27). I attachted client and server log files. I will check the rest after work.

@Owlsroost :
Yes it stays on the emtpy GUI while audio starts paying. Only the background image af the Titan skin is visible.

 

[mm1352000]

MP log shows the delay in the same place, so it looks like we have a pattern.
I'm sorry to say I currently have no idea what's going on.
It looks like a client side problem... but there are no guarantees.

 

[Owlsroost]

Everytime I wake up the living room client from standby and start TV the sound starts, but there is no picture.

Does it only happen after waking from standby, or does it happen every time you start TV?

Looking at the MP log, I was wondering if Power Scheduler might be having problems talking to TV server for some reason:

[2016-12-23 07:28:06,248] [Log ] [MPMain ] [INFO ] - g_Player.OnStarted() rtsp://192.168.1.1:554/stream5.0 media:TV
[2016-12-23 07:28:07,024] [Log ] [3 ] [DEBUG] - PlaneScene: PresentImage() dispose surfaces
[2016-12-23 07:28:11,383] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [DEBUG] - RemoteControl: TCP connect took : 2
[2016-12-23 07:28:11,383] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-23 07:28:12,385] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-23 07:28:13,389] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-23 07:28:14,392] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-23 07:28:15,394] [Log ] [TvClient-TvHome: HeartBeat transmitter thread] [INFO ] - RemoteControl - Connected
[2016-12-23 07:28:25,169] [Log ] [MPMain ] [WARN ] - tvhome:startplay. Phase 2 - 19712 ms - Done starting g_Player.Play()
[2016-12-23 07:28:35,463] [Log ] [PS StandbyWakeup] [DEBUG] - PS: Cannot signal client activity to remote TvServer: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden.


Are there any differences in firewall settings or anti-virus/internet security software between the main HTPC and the Dev PC?

 

[Owlsroost]

It might be an idea to have Task Manager open with MP in windowed mode (after wake from standby), then start TV and check if there is a process using a lot of CPU ?