[ganbu]

Hello there,

I have been suffering a few days now with excessively slow shutdown on Windows 7 Home. It's taking more than 8 minutes to shutdown!
The screen just sits at "Windows Shutting Down" for that period.
Once it shuts down, the time to start again is relatively quick.

This last time was more than 10 minutes - the bulk of it, from the event log below, seems to be "ShutdownKernelTime".

I have tried looking in the Control Panel Performance tools and here are the contents of the event log:


+ System

- Provider

[ Name] Microsoft-Windows-Diagnostics-Performance
[ Guid] {blanked out...}

EventID 200

Version 1

Level 1

Task 4007

Opcode 40

Keywords 0x8000000000010000

- TimeCreated

[ SystemTime] 2012-11-11T14:10:23.533285400Z

EventRecordID 375

- Correlation

[ ActivityID] {blanked out...}

- Execution

[ ProcessID] 1956
[ ThreadID] 1968

Channel Microsoft-Windows-Diagnostics-Performance/Operational

Computer blanked out...-PC

- Security

[ UserID] blanked out...


- EventData

ShutdownTsVersion 1
ShutdownStartTime 2012-11-11T13:54:21.003872000Z
ShutdownEndTime 2012-11-11T14:05:27.260830300Z
ShutdownTime 666256
ShutdownUserSessionTime 4017
ShutdownUserPolicyTime 1
ShutdownUserProfilesTime 65
ShutdownSystemSessionsTime 35855
ShutdownPreShutdownNotificationsTime 33731
ShutdownServicesTime 2010
ShutdownKernelTime 626384
ShutdownRootCauseStepImprovementBits 0
ShutdownRootCauseGradualImprovementBits 0
ShutdownRootCauseStepDegradationBits 0
ShutdownRootCauseGradualDegradationBits 0
ShutdownIsDegradation false
ShutdownTimeChange 0


Google led me here. I have installed the Windows Performance Tool referred to in the thread over here: http://www.msfn.org/...e-tool-kit-wpt/
But I don't know enough to figure out what to do with any of the info/graphs in that file. It's 265MB in size so I can't really upload it here.


I had installed SugarSync recently. Also have dropbox and skydrive. Have disabled these so they don't start up, but the problem persists. There's not much else in the systray; certainly nothing newly installed.

It doesn't happen *every* shutdown; just almost al of them. If I reboot, then almost immediately restart it might or might not take ages. If I then reboot almost immediately a 2nd time it usually seems to shut down in just a few seconds. However, after running for any length of time the system seems to revert back to the slow shutdown.

Does anybody have any ideas what could be wrong? Hardware or software issue? I'm getting to my wits' end

[cluberti]

If you can compress up the ETL file that you generated and place it up on dropbox for us to download, we can have a look at it.

[ganbu]

Wow, that compressed nicely! Down to 36MB.

Dropbox link here: https://www.dropbox....S%2BPOWER_1.zip

Thank you for taking a look and for any help you might be able to offer.

[MagicAndre1981]

the GP service seems to hang and the 2 drivers CLIF.sys and aswsnx.sys (Avast) cause delays. Wait of an advice of cluberti.

This post has been edited by MagicAndre1981: 12 November 2012 - 01:15 AM

[cluberti]

Well, Andre is right - you've got a ton of disk I/O, some of it taking upwards of 6 SECONDS to call by CLFS.sys (common log file system), which is causing the delay (it's going to disk 8, but a shutdown trace doesn't always store drive letters unfortunately). There's definitely an Avast component here, and it looks like it's trying to use the CLFS driver to write to something and can't. However, there's no callstack data here (either -stackwalk wasn't used as part of the trace command, or disablepagingexecutive wasn't set properly before rebooting and tracing), so I can't tell you any more than that with this trace. However, I'd put a greenback on it not reproducing without Avast installed (and why they're still using CLFS for logfile commands on a Vista or newer system is a little beyond me, but that's a different discussion altogether). The reason being I did do an analysis of the In/Out switches via Wait Analysis and found that the vast majority of the waiting time is being spent by the Avast driver waiting on other functions in the Avast driver - more than 50% of the time in just that section of the trace. That's a really, really high number from experience, and points to a potential bug in their code (for whatever reason, I couldn't tell you, as again I have no further debugging ability here with these trace flags).

I'd remove (not disable) Avast, reboot, and then reboot a second time before doing a comparison shutdown.

[ganbu]

Thank you both for your help so far.

I have done a thorough uninstall of Avast and the problem seems better now. Control Panel Event Logger shows about 6-8 seconds shut down, and about 30 seconds start up. I'll keep testing these times over the next several hours and then tomorrow to make sure. (I had originally thought installing Ditto the clipboard manager caused it, since it was the most recent new install and the problem seemed to stop once I'd uninstalled that - of course it surfaced again one or two boots later)

It did occur to me last night after reading your comment about it trying to write to disk 8 that perhaps it might be something to do with my Blackberry Playbook. I have it set us as a network drive so I can drag and drop files onto it. I took that out last night and the shutdown was faster again, but this morning it was back to about 6 minutes so I don't think that was the problem. At least not the main problem anyway, possibly a small part of it? But the Playbook has been set up that way for many months and this shutdown issue is new. However the last Avast program update was about a week or so ago... maybe something in there is conflictng.

I've used Avast for years and always been happy with it. My wife's laptop is also runnng WIndows7 with Avast and she has no slowdowns on that. If it is Avast then it must be something fairly specific to my system. I've checked Avast support forums and there's no sound of anyone else having remotely similar issues.

Here is the most recent event logger entry for shut down and start up (strangely the shut down appears to have happened after the corresponding start up!?)

200 Shut Down:
- System

- Provider

[ Name] Microsoft-Windows-Diagnostics-Performance
[ Guid] {...blanked out...}

EventID 200

Version 1

Level 3

Task 4007

Opcode 40

Keywords 0x8000000000010000

- TimeCreated

[ SystemTime] 2012-11-14T18:25:12.865410200Z

EventRecordID 412

- Correlation

[ ActivityID] {...blanked out...}

- Execution

[ ProcessID] 1644
[ ThreadID] 1688

Channel Microsoft-Windows-Diagnostics-Performance/Operational

Computer Gary-PC

- Security

[ UserID] S-1-5-19


- EventData

ShutdownTsVersion 1
ShutdownStartTime 2012-11-14T18:22:44.956501800Z
ShutdownEndTime 2012-11-14T18:22:52.528119600Z
ShutdownTime 7571
ShutdownUserSessionTime 3507
ShutdownUserPolicyTime 0
ShutdownUserProfilesTime 91
ShutdownSystemSessionsTime 2617
ShutdownPreShutdownNotificationsTime 973
ShutdownServicesTime 1560
ShutdownKernelTime 1446
ShutdownRootCauseStepImprovementBits 0
ShutdownRootCauseGradualImprovementBits 0
ShutdownRootCauseStepDegradationBits 0
ShutdownRootCauseGradualDegradationBits 0
ShutdownIsDegradation false
ShutdownTimeChange 0


100 Boot Up:
- System

- Provider

[ Name] Microsoft-Windows-Diagnostics-Performance
[ Guid] {...blanked out...}

EventID 100

Version 2

Level 3

Task 4002

Opcode 34

Keywords 0x8000000000010000

- TimeCreated

[ SystemTime] 2012-11-14T18:25:12.834210100Z

EventRecordID 411

- Correlation

[ ActivityID] {...blanked out...}

- Execution

[ ProcessID] 1644
[ ThreadID] 4744

Channel Microsoft-Windows-Diagnostics-Performance/Operational

Computer Gary-PC

- Security

[ UserID] S-1-5-19


- EventData

BootTsVersion 2
BootStartTime 2012-11-14T18:23:12.656000300Z
BootEndTime 2012-11-14T18:25:09.527004300Z
SystemBootInstance 187
UserBootInstance 179
BootTime 31923
MainPathBootTime 14523
BootKernelInitTime 17
BootDriverInitTime 952
BootDevicesInitTime 910
BootPrefetchInitTime 47964
BootPrefetchBytes 651206656
BootAutoChkTime 0
BootSmssInitTime 6111
BootCriticalServicesInitTime 143
BootUserProfileProcessingTime 1631
BootMachineProfileProcessingTime 0
BootExplorerInitTime 2863
BootNumStartupApps 28
BootPostBootTime 17400
BootIsRebootAfterInstall false
BootRootCauseStepImprovementBits 1049088
BootRootCauseGradualImprovementBits 512
BootRootCauseStepDegradationBits 0
BootRootCauseGradualDegradationBits 0
BootIsDegradation false
BootIsStepDegradation false
BootIsGradualDegradation false
BootImprovementDelta 13763
BootDegradationDelta 0
BootIsRootCauseIdentified true
OSLoaderDuration 1602
BootPNPInitStartTimeMS 17
BootPNPInitDuration 931
OtherKernelInitDuration 1597
SystemPNPInitStartTimeMS 2525
SystemPNPInitDuration 931
SessionInitStartTimeMS 3460
Session0InitDuration 2168
Session1InitDuration 148
SessionInitOtherDuration 3794
WinLogonStartTimeMS 9571
OtherLogonInitActivityDuration 456
UserLogonWaitDuration 1529

Here is the most recent etl file if anyone wants to see it (around 4MB zipped)
I didn't use a stackwalk switch in the command because I just copy-pasted the line in that other thread. I don't know what parameters to include if I try and add stackwalk or anything different.

https://www.dropbox....S%2BPOWER_2.zip

Thanks again! I'll keep you posted if there are any changes in the next few hours.

[MagicAndre1981]

 <timing shutdownTime="7778" servicesShutdownDuration="1590">

shutdown is 7.8s, which is fine now.

[ganbu]

My hopes are dashed.
It went through 3 reboots earlier today, with apparent success, but I just tried again and the problem is still there. Just under 9 minutes this time.

Strangely, there is no entry in the event log except the fact of a start up event ID100 taking 29,361ms.
But here is the latest etl file, zipped down from 189MB to 23MB

https://www.dropbox....2BPOWER_1_3.zip

[MagicAndre1981]

the CLFS.sys seems the cause it.

http://msdn.microsof...y/ff565363.aspx

But I have no idea how to see which tool uses it. Wait what cluberti tells you.

[cluberti]

Well, this is very, very odd. BrYNSync.exe is continuously making calls through services.exe to the print spooler. It appears this is some sort of Brother printer service, talking to a .dll on the system, which is continuously calling some function I don't understand. However, I can tell that at the beginning of the shutdown trace, it appears that the thread this service is running goes into the advapi32!ScSvcctrlThreadW function, which calls a service's ServiceMain (startup) routine. It then enters into doing some functions in the BrMonitor.dll driver, which I don't have symbols for (Microsoft makes their symbols for most products public, so we can debug, but the Brother symbols are not so it's a black box right now). This appears to take almost all of the 500 second delay here, and when that stops, the box continues shutting down properly.

Have you updated any drivers, or installed anything new before this happened? In the very least, it seems like the Brother printer software on the machine is causing you problems here, but again, I have no idea why. There's no way to dig further in this trace, but without all the Avast spam in the logs it becomes quite obvious the printer driver has a service, and that service is refusing to shut down properly or in a timely manner.

[ganbu]

Oh dear. If it's the Brother drivers then I have a hunch this is going to be Adobe Acrobat. I installed that a few weeks ago.
The Brother is a multifunction printer/'scanner/copier, and Acrobat is tied in to the scanner for sure.

I have a vague memory of some kind of Brother update recently but I don't think it was drivers, and I also think that was before I installed Acrobat.

I've uninstallled Acrobat for now, and deactivated the key so I can hopefully reuse it.

Shutdown now seems normal again for a couple of reboots in a row. I'll run restarts periodically over the next day or so to see if the shutdown issue has gone away. If it has then I'll try the Adobe on another box, maybe the laptop, and see what happens.

Thanks, cluberti, and Andre too, for all your help.

[ganbu]

Just a quick final post for future reference. It apparently must have been something about Adobe Acrobat and my Brother scanner drivers. I've been rebooting normally for the past 3-4 days, no slowdowns, everything seems fine again.

It doesn't seem to be Acrobat itself that's the problem. I've been able to reuse the key and installed it on the laptop this time, with no ill effects there. It must just be something about the drivers/updates I have on this box.

Thanks again for the help. You were brilliant!

[cluberti]

Good to hear it's working again