Windows 7 WMI validation hotfix improves slow network logins

Like many other system administrators of Windows 7 systems, I have been experiencing some very slow logins on domain joined Windows 7 systems.

Some of the common factors of these slow network logins include:

• Computers that multiple users log into, for example Education computers where 100s of users log in
• Computers with a large number of group policies
• First time logons
• Windows 7 machines
• Machines hanging on "Applying user settings" or more commonly "Preparing your desktop"

The problem normally develops over time and as more and more users have logged in at least once, the login process slows even more. Some users on Microsoft forums are reporting login times as long as 30 minutes, but in my case the maximum times are 2-3 minutes. Fortunately for users that have previously logged in, login times are significantly quicker, but in Education using the same computer twice can be a rare occurrence.

After noticing some WMI and group policy based event log entries I decided to do some debug logging of the group policy service. This can potentially give me some in depth information as to what is happening during the 2-3 minute wait during login. 


Enabling the Group Policy debug logging

1. Open regedit and navigate to
HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Diagnostics

2. Set the following value
"GPSvcDebugLevel"=dword:00030002

3. It is best to reboot and then login with an account that has previously never logged into that specific system.

4. After the user has logged in you will find the log located at %WINDIR%\debug\usermode\gpsvc.log.

Make sure you note the time of when you start the login and when you successfully make it to the desktop, this should help your identify the events in the log.

5. Make sure you remove the registry value when your done or else you may fill your hard drive with GPSVC logs.

I recommend using a tool like the SMS Trace32.exe to view your logs, it is much easier to search and will highlight warning and error events.

There is also a neat tool by Syspro called Policy Reporter that is able to enable, log and report on Group Policy Service logs in a more "user friendly" manner, its worth checking out.



Attempting to interpret the logs

Interpreting the gpsvc.log is easier said than done and unfortunately there doesn't seem to be much official documentation to help you do so. I found the easiest thing to do is look for significant time gaps in the logs and drill down on them more intensely.

I found the below section of the log repeated across a number of affected machines I tested. It references S-1-5-18 which is the SID for "Local System" and mentions "Caller requesting for user notification/lock is from session 0" and then hangs for around 1m 30s before the next log entry.

This time of 18:24:47 is during my "hang" period where I should already be at the desktop. 

GPSVC(388.b68) 18:24:47:795 Target = S-1-5-18
GPSVC(388.b68) 18:24:47:795 Could not find user by sid, finding user by session id
GPSVC(388.b68) 18:24:47:795 Caller requesting for user notification/lock is from session 0
GPSVC(c64.c78) 18:24:47:795 Client_RegisterForNotification: User = S-1-5-18, changenumber = 0
GPSVC(c64.c78) 18:24:47:796 CGPNotify::RegisterForNotification: Exiting with status = 0
GPSVC(388.b68) 18:24:47:796 Could not find user by sid, finding user by session id
GPSVC(388.b68) 18:24:47:796 Caller requesting for user notification/lock is from session 0
GPSVC(36c.420) 18:26:10:537 CGPNotify::UnregisterNotification: Entering with event 0x4ec
GPSVC(36c.420) 18:26:10:537 CGPNotify::AbortAsyncRegistration: No asyn registration is pending
GPSVC(36c.420) 18:26:10:537 CGPNotify::UnregisterNotification: Canceling pending calls
GPSVC(36c.420) 18:26:10:538 Client_CompleteNotificationCall: failed with 0x71a
GPSVC(36c.420) 18:26:10:538 CGPNotify::UnregisterNotification: Cancelled pending calls
GPSVC(36c.420) 18:26:10:538 CGPNotify::UnregisterNotification: Exiting with dwStatus = 0x0
GPSVC(388.f0c) 18:26:22:944 CGPNotify::RegisterForNotification: Entering with target Machine and event 0xdb0
GPSVC(388.f0c) 18:26:22:988 Client_InitialRegisterForNotification: User = machine, changenumber = 0
GPSVC(388.b68) 18:26:23:000 Target = Machine
GPSVC(388.f0c) 18:26:23:000 Client_RegisterForNotification: User = machine, changenumber = 0
GPSVC(388.f0c) 18:26:23:026 CGPNotify::RegisterForNotification: Exiting with status = 0

After trying a number of experimental techniques to improve the login speed I only managed to partially destroy an OS, so I gave up for a few weeks, that is until I saw Microsoft hotfix KB 2617858. 
 

Hotfix KB 2617858 to the rescue

This hotfix is described as fixing "Unexpectedly slow startup or logon process in Windows Server 2008 R2 or in Windows 7". This is down a slightly different path than the group policy logs I was examining above but ties in with group policy WMI filtering and the WMI event log errors I previously found.

The error is caused by Windows Management Instrumentation (WMI) performing a full validation of the WMI respository when it is not required. This operation takes a long time and delays the login process. This hotfix prevents this full validation from occurring and can alleviate the login delays.

I found this hotfix to significantly improve login times for "first time" logins. While the login is not nearly as fast as it is for users that have previously logged onto the system, it only takes around 1 minutes as opposed to the 1-4 minutes it took in the past.

I have started deploying this hotfix to one heavily affected area in my environment, as soon as I can confirm there are no caveats I will roll it out to all affected systems.

If your problem still persists after applying this hotfix then another debugging solution might be to use Sysinternals Process Monitor in "boot logging" mode. I tried this method but the resultant log was some 8 million lines and extremely hard to examine. This method didn't work for me but depending on your problem it may be another troubleshooting alternative.