Picture delayed when turning on TV (Sound OK) (1 Viewer)

[Marcus Venturi]

After changing from single seat to multi seat I have still problems with my HTPC (system specs "HTPC") when turning on TV.
The sound starts immediately but there is no picture for 30 seconds. After 30 seconds the picture appears and switching between channels is fast then. On my development PC (system specs "Desktop") starting TV takes 5 seconds, Therefore I assume that the problem is not the server.
IPV6 is already turned off.
See MediaPortal.log at:

[2016-01-20 19:03:25,248] [Log ] [MPMain ] [INFO ] - tvhome:startplay
[2016-01-20 19:03:26,233] [Log ] [MPMain ] [INFO ] - g_Player.OnStarted() rtsp://192.168.1.1:554/stream5.0 media:TV
...
[2016-01-20 19:03:57,256] [Log ] [MPMain ] [WARN ] - tvhome:startplay. Phase 2 - 31997 ms - Done starting g_Player.Play()

Really strange...

 

[mm1352000]

Hi Marcus

It seems like this only happens on first channel selection after resume:

[2016-01-20 13:45:55,420] [Log ] [MPMain ] [INFO ] - Main: WM_POWERBROADCAST (PBT_APMRESUMEAUTOMATIC)
...
[2016-01-20 13:46:22,506] [Log ] [MPMain ] [INFO ] - g_Player.OnStarted() rtsp://192.168.1.1:554/stream5.0 media:TV
[2016-01-20 13:46:32,325] [Log ] [MPMain ] [WARN ] - tvhome:startplay. Phase 2 - 10682 ms - Done starting g_Player.Play()

[2016-01-20 19:03:01,413] [Log ] [MPMain ] [INFO ] - Main: WM_POWERBROADCAST (PBT_APMRESUMEAUTOMATIC)
...
[2016-01-20 19:03:26,233] [Log ] [MPMain ] [INFO ] - g_Player.OnStarted() rtsp://192.168.1.1:554/stream5.0 media:TV
[2016-01-20 19:03:57,256] [Log ] [MPMain ] [WARN ] - tvhome:startplay. Phase 2 - 31997 ms - Done starting g_Player.Play()

Can you confirm?


It looks like TsReader thinks video is playing fine during the time you say there is no picture:
[collapse]
[2016-01-20 19:03:27,873] [ e63bc58] [1480] - Demux : Video to render 1.035 Sec
[2016-01-20 19:03:28,003] [ e63bc58] [1480] - Demux : Video to render 0.985 Sec
[2016-01-20 19:03:28,050] [ e63bc58] [1480] - Demux : Video to render 0.978 Sec
[2016-01-20 19:03:28,170] [ e63bc58] [1480] - Demux : Video to render 0.978 Sec
[2016-01-20 19:03:29,391] [ e63bc58] [1480] - Demux : Video to render 0.917 Sec
[2016-01-20 19:03:29,670] [ e63bc58] [1480] - Demux : Video to render 0.878 Sec
[2016-01-20 19:03:29,791] [ e63bc58] [1480] - Demux : Video to render 0.877 Sec
[2016-01-20 19:03:29,923] [ e63bc58] [1480] - Demux : Video to render 0.865 Sec
[2016-01-20 19:03:29,990] [ e63bc58] [1480] - Demux : Video to render 0.838 Sec
[2016-01-20 19:03:30,070] [ e63bc58] [1480] - Demux : Video to render 0.838 Sec
[2016-01-20 19:03:30,270] [ e63bc58] [1480] - Demux : Video to render 0.758 Sec
[2016-01-20 19:03:41,869] [ e63bc58] [1480] - Demux : Video to render 0.679 Sec
[2016-01-20 19:03:41,910] [ e63bc58] [1480] - Demux : Video to render 0.678 Sec
[2016-01-20 19:03:42,070] [ e63bc58] [1480] - Demux : Video to render 0.638 Sec[/collapse]


Unfortunately your MediaPortal log file log level is "info" so I can't see the full picture from the MP side. New debug level log files are needed please. Also, please reproduce the problem with all plugins disabled (Watchdog option 1). There's a distinct possibility that the problem is caused by a plugin taking a long time to handle the g_Player OnStarted() event.

Regards,
mm


P.S.: @Stéphane Lenclud
There are some interesting HID related entries in these log files...
[collapse]
[2016-01-20 08:26:04,643] [Error ] [MPMain ] [ERROR] - InputDevices - WndProc - exception caught from InputDevice: MediaPortal.InputDevices.HidListener System.Exception: HidDevice: GetDeviceInfo failed: 6
at SharpLib.Hid.Device..ctor(IntPtr hRawInputDevice)
at SharpLib.Hid.Event..ctor(Message aMessage, HidEventRepeatDelegate aRepeatDelegate, Boolean aRepeat, Int32 aRepeatDelayInMs, Int32 aRepeatSpeedInMs)
at SharpLib.Hid.Handler.ProcessInput(Message& aMessage)
at MediaPortal.InputDevices.HidListener.WndProc(Message& msg, Action& action, Char& key, Keys& keyCode)
at MediaPortal.InputDevices.InputDevices.WndProc(Message& msg, Action& action, Char& key, Keys& keyCode)]/collapse]

...but it's strange. The log file says that Marcus is running MP 1.13 [final]:
[2016-01-20 08:25:59,680] [Log ] [MPMain ] [INFO ] - Main: MediaPortal v1.13.0.0 is starting up on Windows 7 ( Service Pack 1 ) [6.1.7601.65536]

...and yet:
[2016-01-20 08:26:04,483] [Log ] [MPMain ] [INFO ] - MAP: using custom mappings for Microsoft MCE
[2016-01-20 08:26:04,493] [Log ] [MPMain ] [INFO ] - MCE: MCE remote enabled

Marcus, is this a customised build?

 

[Stéphane Lenclud]

Hi Marcus

It seems like this only happens on first channel selection after resume:

[2016-01-20 13:45:55,420] [Log ] [MPMain ] [INFO ] - Main: WM_POWERBROADCAST (PBT_APMRESUMEAUTOMATIC)
...
[2016-01-20 13:46:22,506] [Log ] [MPMain ] [INFO ] - g_Player.OnStarted() rtsp://192.168.1.1:554/stream5.0 media:TV
[2016-01-20 13:46:32,325] [Log ] [MPMain ] [WARN ] - tvhome:startplay. Phase 2 - 10682 ms - Done starting g_Player.Play()

[2016-01-20 19:03:01,413] [Log ] [MPMain ] [INFO ] - Main: WM_POWERBROADCAST (PBT_APMRESUMEAUTOMATIC)
...
[2016-01-20 19:03:26,233] [Log ] [MPMain ] [INFO ] - g_Player.OnStarted() rtsp://192.168.1.1:554/stream5.0 media:TV
[2016-01-20 19:03:57,256] [Log ] [MPMain ] [WARN ] - tvhome:startplay. Phase 2 - 31997 ms - Done starting g_Player.Play()

Can you confirm?


It looks like TsReader thinks video is playing fine during the time you say there is no picture:
[collapse]
[2016-01-20 19:03:27,873] [ e63bc58] [1480] - Demux : Video to render 1.035 Sec
[2016-01-20 19:03:28,003] [ e63bc58] [1480] - Demux : Video to render 0.985 Sec
[2016-01-20 19:03:28,050] [ e63bc58] [1480] - Demux : Video to render 0.978 Sec
[2016-01-20 19:03:28,170] [ e63bc58] [1480] - Demux : Video to render 0.978 Sec
[2016-01-20 19:03:29,391] [ e63bc58] [1480] - Demux : Video to render 0.917 Sec
[2016-01-20 19:03:29,670] [ e63bc58] [1480] - Demux : Video to render 0.878 Sec
[2016-01-20 19:03:29,791] [ e63bc58] [1480] - Demux : Video to render 0.877 Sec
[2016-01-20 19:03:29,923] [ e63bc58] [1480] - Demux : Video to render 0.865 Sec
[2016-01-20 19:03:29,990] [ e63bc58] [1480] - Demux : Video to render 0.838 Sec
[2016-01-20 19:03:30,070] [ e63bc58] [1480] - Demux : Video to render 0.838 Sec
[2016-01-20 19:03:30,270] [ e63bc58] [1480] - Demux : Video to render 0.758 Sec
[2016-01-20 19:03:41,869] [ e63bc58] [1480] - Demux : Video to render 0.679 Sec
[2016-01-20 19:03:41,910] [ e63bc58] [1480] - Demux : Video to render 0.678 Sec
[2016-01-20 19:03:42,070] [ e63bc58] [1480] - Demux : Video to render 0.638 Sec[/collapse]


Unfortunately your MediaPortal log file log level is "info" so I can't see the full picture from the MP side. New debug level log files are needed please. Also, please reproduce the problem with all plugins disabled (Watchdog option 1). There's a distinct possibility that the problem is caused by a plugin taking a long time to handle the g_Player OnStarted() event.

Regards,
mm


P.S.: @Stéphane Lenclud
There are some interesting HID related entries in these log files...
[collapse]
[2016-01-20 08:26:04,643] [Error ] [MPMain ] [ERROR] - InputDevices - WndProc - exception caught from InputDevice: MediaPortal.InputDevices.HidListener System.Exception: HidDevice: GetDeviceInfo failed: 6
at SharpLib.Hid.Device..ctor(IntPtr hRawInputDevice)
at SharpLib.Hid.Event..ctor(Message aMessage, HidEventRepeatDelegate aRepeatDelegate, Boolean aRepeat, Int32 aRepeatDelayInMs, Int32 aRepeatSpeedInMs)
at SharpLib.Hid.Handler.ProcessInput(Message& aMessage)
at MediaPortal.InputDevices.HidListener.WndProc(Message& msg, Action& action, Char& key, Keys& keyCode)
at MediaPortal.InputDevices.InputDevices.WndProc(Message& msg, Action& action, Char& key, Keys& keyCode)]/collapse]

...but it's strange. The log file says that Marcus is running MP 1.13 [final]:
[2016-01-20 08:25:59,680] [Log ] [MPMain ] [INFO ] - Main: MediaPortal v1.13.0.0 is starting up on Windows 7 ( Service Pack 1 ) [6.1.7601.65536]

...and yet:
[2016-01-20 08:26:04,483] [Log ] [MPMain ] [INFO ] - MAP: using custom mappings for Microsoft MCE
[2016-01-20 08:26:04,493] [Log ] [MPMain ] [INFO ] - MCE: MCE remote enabled

Marcus, is this a customised build?

Yes it's the custom build that catches exceptions from input handlers. Marcus has some kind of USB Wii kinetic receiver that's causing this.
Not sure what the MCE logs are. Some left over I guess.

 

[Marcus Venturi]

Unfortunately your MediaPortal log file log level is "info" so I can't see the full picture from the MP side. New debug level log files are needed please. Also, please reproduce the problem with all plugins disabled (Watchdog option 1). There's a distinct possibility that the problem is caused by a plugin taking a long time to handle the g_Player OnStarted() event.

I will provide debug logs. Yesterday the TV was used by the kids, so just took the existing files as admin from the C$ share while MediaPortal was running (assuming debug was on, which was not the case).

 

[azzuro]

i can have same issue than you, it's an random issue.
and this one was more present before the rework of sebastiii on resume stuff.

Edit: have ou Minidisplay ?

 

[azzuro]

@mm1352000 : sure i provide you log the next time. ( but i have little memory to provide log on forum, but don't know where )

@Marcus Venturi : you use rtsp, i will back to rtsp too, so, ( i use UNC, now )

 

[azzuro]

@mm1352000 :
https://forum.team-mediaportal.com/threads/livetv-blackscreen-after-resume.131071/#post-1139107
hey hey

since 07/2015, new logs must be the best.

 

[Marcus Venturi]

i can have same issue than you, it's an random issue.
and this one was more present before the rework of sebastiii on resume stuff.

Edit: have ou Minidisplay ?

No, but I'm using MPDisplay. I can confirm that it does not happen every time, but that's enough for a significant reduction of the WAF-factor.

 

[azzuro]

No, but I'm using MPDisplay.

I think nothing related.

 

[mm1352000]

As I said in my previous reply: it looks like it only happens on the first channel selection after resume. Can either of you confirm that? ...or do you think it also happens at other times as well?