ganbu Posted November 12, 2012 Posted November 12, 2012 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: 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 Posted November 12, 2012 Posted November 12, 2012 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 Posted November 12, 2012 Author Posted November 12, 2012 Wow, that compressed nicely! Down to 36MB. Dropbox link here: https://www.dropbox.com/s/8hpjw8ei0z4ffky/shutdown_BASE%2BCSWITCH%2BDRIVERS%2BPOWER_1.zipThank you for taking a look and for any help you might be able to offer.
MagicAndre1981 Posted November 12, 2012 Posted November 12, 2012 (edited) the GP service seems to hang and the 2 drivers CLIF.sys and aswsnx.sys (Avast) cause delays. Wait of an advice of cluberti. Edited November 12, 2012 by MagicAndre1981
cluberti Posted November 14, 2012 Posted November 14, 2012 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 Posted November 14, 2012 Author Posted November 14, 2012 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.com/s/spq1b598ge46gqa/shutdown_BASE%2BCSWITCH%2BDRIVERS%2BPOWER_2.zipThanks again! I'll keep you posted if there are any changes in the next few hours.
MagicAndre1981 Posted November 14, 2012 Posted November 14, 2012 <timing shutdownTime="7778" servicesShutdownDuration="1590">shutdown is 7.8s, which is fine now.
ganbu Posted November 15, 2012 Author Posted November 15, 2012 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 23MBhttps://www.dropbox.com/s/tt325zrr2oskfnb/shutdown_BASE%2BCSWITCH%2BDRIVERS%2BPOWER_1_3.zip
MagicAndre1981 Posted November 15, 2012 Posted November 15, 2012 the CLFS.sys seems the cause it.http://msdn.microsoft.com/en-us/library/ff565363.aspxBut I have no idea how to see which tool uses it. Wait what cluberti tells you.
cluberti Posted November 17, 2012 Posted November 17, 2012 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 Posted November 18, 2012 Author Posted November 18, 2012 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 Posted November 21, 2012 Author Posted November 21, 2012 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!
Recommended Posts
Please sign in to comment
You will be able to leave a comment after signing in
Sign In Now