TV Service taking long while to shutdown, delaying Windows shutdown/reboot (1 Viewer)

[doveman]

MediaPortal Version: 1.4.0

Description
I've noticed that when shutting down/rebooting Windows, it gets stuck on "TVService is shutting down" for about 10s (I'm using VerboseStatus to see the shutdown steps).
I've set WaitToKillServiceTimeout to 2000 (2s) but this doesn't seem to make any difference. I did have TVService set to Restart on Failure for all three settings so thought it was maybe restarting and having to be killed again but I changed them all to Take No Action and it still takes 10s for it to shutdown.
In the System log I see this
"The TVService service did not shut down properly after receiving a preshutdown control."
If I go into Services and manually Stop TVService, it does shutdown within 2s.
I'm not actually using MP on this system at the moment and don't even have an aerial connected to the tuner card, so ignore any errors related to that in the logs. I don't suppose the logs will help much with this problem and it's more a matter of tweaking things to make it behave better.

Steps to Reproduce:
Shutdown Windows

 

[mm1352000]

Hello doveman

Please can you refer to an example in your log files? In other words, please specify a date and time when you see this occurring.
I see this:

[2013-07-15 21:11:33,543] [Log ] [PS StandbyWakeup] [DEBUG] - PS: System will go to standby after Windows idle timeout
[2013-07-15 21:11:42,963] [Log ] [TVService] [INFO ] - TvService is beeing stopped
...
[2013-07-15 21:11:43,048] [Log ] [TVService] [INFO ] - TV Service: stopped

[2013-07-15 20:58:02,413] [Log ] [PS StandbyWakeup] [DEBUG] - PS: System will go to standby after Windows idle timeout
[2013-07-15 20:58:06,016] [Log ] [TVService] [INFO ] - TvService is beeing stopped
...
[2013-07-15 20:58:06,079] [Log ] [TVService] [INFO ] - TV Service: stopped

[2013-07-15 19:28:09,595] [Log ] [PS StandbyWakeup] [DEBUG] - PS: Requests preventing Windows standby: [PROCESS] \Device\HarddiskVolume1\Windows\explorer.exe
[2013-07-15 19:28:23,744] [Log ] [TVService] [INFO ] - TvService is beeing stopped
...
[2013-07-15 19:28:23,806] [Log ] [TVService] [INFO ] - TV Service: stopped

[2013-07-15 19:19:21,930] [Log ] [PS StandbyWakeup] [DEBUG] - PS: System will go to standby after Windows idle timeout
[2013-07-15 19:19:36,032] [Log ] [TVService] [INFO ] - TvService is beeing stopped
...
[2013-07-15 19:19:36,126] [Log ] [TVService] [INFO ] - TV Service: stopped

[2013-07-15 19:15:52,819] [Log ] [PS StandbyWakeup] [DEBUG] - PS: System will go to standby after Windows idle timeout
[2013-07-15 19:16:07,277] [Log ] [TVService] [INFO ] - TvService is beeing stopped
...
[2013-07-15 19:16:07,387] [Log ] [TVService] [INFO ] - TV Service: stopped

[2013-07-15 17:27:41,234] [Log ] [PS StandbyWakeup] [DEBUG] - PS: System will go to standby after Windows idle timeout
[2013-07-15 17:27:50,453] [Log ] [TVService] [INFO ] - TvService is beeing stopped
...
[2013-07-15 17:27:50,531] [Log ] [TVService] [INFO ] - TV Service: stopped

In other words, if there is a delay I think it is a delay in TV service receiving the shutdown command or somehow due to an interaction with powerscheduler.

As it stands I don't see any evidence of an issue that we can look into...

mm

 

[catavolt]

I can confirm the issue!
I was wondering why shutting down Windows took so long since some time ago (approx. 30 secs).
Now I stopped TVService manually - and voilá: Windows shuts down as before (approx 10 secs).
I tried this five times now: Shutdown Windows w/o manually stopping TVService = approx. 30 secs, stopping TVService manually before shutting down Windows = 10 secs!
BTW: I was already searching a lot of forums why the shutdown time increased dramatically....
I´m talking about shutting down Windows after MP was stopped or even not running at all

 

[mm1352000]

I can confirm the issue!

Same comments apply as for doveman - not enough info here yet to confirm.
Please provide:

1. Log files for delayed and non delayed shutdown.
2. Date and time when you attempt to shutdown (referring to the provided logs).
3. Dates and times when you see or don't see the delay (referring to the provided logs).
4. Confirm whether you use PowerScheduler or PowerScheduler++.
5. Specify how you're shutting down Windows.

Missing a lot of info still!

 

[catavolt]

As I said above: MP is already shut - so nothing in any MP log
I don´t run any PowerScheduler
I thought my explanation above was clear enough

 

[mm1352000]

As I said above: MP is already shut - so nothing in any MP log

The MP log is irrelevant. I'm talking about the TV service logs!

I don´t run any PowerScheduler

Okay thanks.

I thought my explanation above was clear enough

Nope.
Please provide the times as requested...

 

[doveman]

I can confirm the issue!

Same comments apply as for doveman - not enough info here yet to confirm.
Please provide:

1. Log files for delayed and non delayed shutdown.
2. Date and time when you attempt to shutdown (referring to the provided logs).
3. Dates and times when you see or don't see the delay (referring to the provided logs).
4. Confirm whether you use PowerScheduler or PowerScheduler++.
5. Specify how you're shutting down Windows.

Missing a lot of info still!

Hi mm

I've just done two shutdown traces (attached), one at 12:11 without TVService running, which took 8-10s and another at 12:16 with TVService running, which took 20-25s. I'm using PS++ and shutting down using the Start Menu. Windows Update service and then Eventlog service are the two services that stop before it gets to TVService.

The traces (summary_shutdown2.xml is the one with TVService running) show:

Without TVService running:
	  <intervals>
		<interval name="WaitForWinstationShutdown" startTime="1491" endTime="1524" duration="33"/>
		<interval name="PreShutdownNotification" startTime="1600" endTime="2910" duration="1310"/>

With TVService running:
	  <intervals>
		<interval name="WaitForWinstationShutdown" startTime="1561" endTime="1583" duration="22"/>
		<interval name="PreShutdownNotification" startTime="1658" endTime="23625" duration="21967"/>

so you can see, with TVService running the PreShutdownNotification stages takes about 20s longer.

I found this information about this stage:

"What Happens in SystemSession

This phase includes two subphases:
• Preshutdown notification. Windows serially shuts down all services that registered to receive preshutdown notifications. Ordered services—services that have set up the shutdown order of dependent services—are shut down before non-ordered services.
• Shutdown notification. All services that registered to receive shutdown notifications are shut down in parallel.

If all services have not exited after 20 seconds (in Windows Vista) or 12 seconds (in Windows 7), the system continues the shutdown. Processes and services that do not shut down in a timely manner are left running as the system shuts down.

SystemSession Performance Vulnerabilities

In the preshutdown notification subphase, the SCM serializes the waits. Therefore, these services block system shutdown until they exit or until the wait hint time-out expires.
Services are not guaranteed to have enough time to finish all their work in the shutdown notification subphase before the system shuts down."

Quite why TVService stops in 2s when done manually but causes this delay when doing a Windows shutdown I'm not sure. It may be that it's not properly notifying Windows that it has stopped and so Windows is waiting this 12 seconds before continuing anyway.

 

[mm1352000]

The key to progress here is to be able to differentiate between whether the problem is:

1. TV Server not receiving the stop request in a timely fashion.
2. TV Server actually taking a long time to stop when stopped automatically.
3. Windows not detecting that the TV service has stopped.

From the previously supplied logs I don't think the issue is (2).
Differentiating between (1) and (3) requires very specific timing. Essentially we need to know when you click on OK to shutdown so we can see how long it takes before the "TvService is beeing stopped" message is logged.

 

[FreakyJ]

so maybe the evntlog could give us the answer at which time the system goes to sleep, because we need the seconds

Information 15.07.2013 22:31:41 Kernel-Power 42 (64)

(this is from my computer entering the sleep state), but it should also log the shutdown time. In combination with the tv server log files it should be helpful, right?

Edit: the event details tell you which power state it is, so this is important, too
e.g

The system is entering sleep.

Sleep Reason: Application API

 

[doveman]

Hmm, seems the attachments disappeared somehow. I've re-attached them.

I can see from the SYSTEM log that the first events when shutting down were at

12:07:18

12:11:06

12:16:21