[gptalk] Re: Small login delay

  • From: Thorbjörn Sjövold <thorbjorn.sjovold@xxxxxxxxxxxxxxx>
  • To: <gptalk@xxxxxxxxxxxxx>
  • Date: Thu, 3 May 2007 22:44:24 +0200

I do not follow your idea that the logon scripts cannot be responsible, this 
part of userenv.log is mostly from the loading of a user profile, from this log 
I can see that Winlogon.exe is with PID 1432 (0x598) is running a thread with 
ID 1436 (59c) that is loading the user profile for user gdifcio, i.e gdifcio is 
currently logging on, and then after that cmd.exe loads usernv.dll to prepare 
for a API call such as EnterCriticalPolicySection, that is what the line 
"USERENV(7e0.7c) 10:31:52:500 LibMain: Process Name:  
C:\WINDOWS\system32\cmd.exe" really means.  


When cmd.exe or any well written application that is managed by group policy is 
accessing its settings it calls the EnterCriticalPolicySection that is 
implemented in userenv.dll. EnterCriticalPolicySection is a blocking API, 
meaning that it Group Policy is actually being processed when the API is called 
the thread that makes the call freezes until all GP extensions have finished 
processing, this is of course to make sure that the settings are consistent. 
Just start cmd.exe on a XP box anytime and you will see a new entry in 
userenv.log, even notepad.exe does this :) So if the case is here that Group 
Policy is being processed and cmd.exe is called then this could take extra time 
to process since cmd.exe will simply wait until GP has finished processing.


It could still be one of the services that you refer to that calls cmd.exe, but 
have you tried to remove the logon scripts to be sure that it is not related to 
this.? Also are you running your logon scripts synchronously or a synchronously?





Thorbjörn Sjövold

Special Operations Software

www.specopssoft.com <http://www.specopssoft.com> 

thorbjorn.sjovold a t specopssoft.com


Download our free tool for remote Gpupdate with graphical reporting, 





From: gptalk-bounce@xxxxxxxxxxxxx [mailto:gptalk-bounce@xxxxxxxxxxxxx] On 
Behalf Of Difarnecio, Gino (Citco)
Sent: den 3 maj 2007 17:36
To: gptalk@xxxxxxxxxxxxx
Subject: [gptalk] Small login delay


I am not certain that this problem is policy related. Seeing as we have some 
policy based scripts, I thought it might be linked.

We are experiencing some small login delays on all of our systems. It seems 
that if we disable all of the non-microsoft services we can get a login down to 
about 15-20 seconds. Meaning, this is how long it takes for the desktop to be 
presented.  However, upon enabling all of the non-windows, yet equally 
necessary services, we have login delays running over 1.5 minutes. 

I've enabled the Userenv logging and am able to determine that the delay takes 
place at the computer and not the user level. It seems that the delay is caused 
at the profile loading part of the process. The exact process causing the delay 
is CMD.exe. Unfortunately, I am not sure what triggers the call to this 
process. I have tried disabling each of the process, one by one to try and 
narrow it down. It seems that enabling a single process, doesn't matter which 
one, will introduce this delay and the call to cmd.exe.

We have some polices that contain login scripts, but none of these should 
really come into play until the user logins. I have attached the relevant 
section of the Userenv.log file. 

Any help or guidance with this issue would be immensely appreciated.

USERENV(598.59c) 10:31:37:312 LoadUserProfile: Entering, hToken = <0x96c>, 
lpProfileInfo = 0x6e3e0

USERENV(598.59c) 10:31:37:312 LoadUserProfile: lpProfileInfo->dwFlags = <0x0>

USERENV(598.59c) 10:31:37:312 LoadUserProfile: lpProfileInfo->lpUserName = 

USERENV(598.59c) 10:31:37:312 LoadUserProfile: NULL central profile path

USERENV(598.59c) 10:31:37:312 LoadUserProfile: lpProfileInfo->lpDefaultPath = 
<\\ADDC27\netlogon\Default User>

USERENV(598.59c) 10:31:37:312 LoadUserProfile: NULL server name

USERENV(598.59c) 10:31:37:312 LoadUserProfile: User sid: 

USERENV(598.59c) 10:31:37:312 CSyncManager::EnterLock 

USERENV(598.59c) 10:31:37:312 CSyncManager::EnterLock: No existing entry found

USERENV(598.59c) 10:31:37:312 CSyncManager::EnterLock: New entry created

USERENV(598.59c) 10:31:37:312 CHashTable::HashAdd: 
S-1-5-21-3061726268-1491933618-2623018998-10550 added in bucket 9

USERENV(598.59c) 10:31:37:312 LoadUserProfile: Wait succeeded. In critical 

USERENV(598.59c) 10:31:37:312 RestoreUserProfile:  Entering

USERENV(598.59c) 10:31:37:312 RestoreUserProfile:  User is a Admin

USERENV(598.59c) 10:31:37:312 IsCentralProfileReachable:  Entering

USERENV(598.59c) 10:31:37:312 IsCentralProfileReachable:  Null path.  Leaving

USERENV(598.59c) 10:31:37:312 RestoreUserProfile:  Profile path = <>

USERENV(598.59c) 10:31:37:312 ExtractProfileFromBackup:  A profile already 

USERENV(598.59c) 10:31:37:312 PatchNewProfileIfRequred: A profile already 
exists with the current sid, exitting

USERENV(598.59c) 10:31:37:312 CreateLocalProfileKey:  Not setting additional 

USERENV(598.59c) 10:31:37:312 GetExistingLocalProfileImage:  Found entry in 
profile list for existing local profile

USERENV(598.59c) 10:31:37:312 GetExistingLocalProfileImage:  Local profile 
image filename = <%SystemDrive%\Documents and Settings\gdifcio>

USERENV(598.59c) 10:31:37:312 GetExistingLocalProfileImage:  Expanded local 
profile image filename = <C:\Documents and Settings\gdifcio>

USERENV(598.59c) 10:31:37:421 GetExistingLocalProfileImage:  No local mandatory 
profile.  Error = 2

USERENV(598.59c) 10:31:37:515 GetExistingLocalProfileImage:  Found local 
profile image file ok <C:\Documents and Settings\gdifcio\ntuser.dat>

USERENV(598.59c) 10:31:37:765 GetExistingLocalProfileImage:  Failed to query 
low profile unload time with error 2

USERENV(598.59c) 10:31:37:796 Local Existing Profile Image is reachable

USERENV(598.59c) 10:31:37:796 Local profile name is <C:\Documents and 

USERENV(598.59c) 10:31:37:796 RestoreUserProfile:  No central profile.  
Attempting to load local profile.

USERENV(598.59c) 10:31:38:500 MyRegLoadKey: Returning 00000000

USERENV(598.59c) 10:31:39:468 MyRegLoadKey: Returning 00000000

USERENV(598.59c) 10:31:39:468 CreateClassHive: existing user classes hive found

USERENV(598.59c) 10:31:39:468 RestoreUserProfile:  About to Leave.  Final 
Information follows:

USERENV(598.59c) 10:31:39:468 Profile was successfully loaded.

USERENV(598.59c) 10:31:39:468 lpProfile->lpRoamingProfile = <>

USERENV(598.59c) 10:31:39:468 lpProfile->lpLocalProfile = <C:\Documents and 

USERENV(598.59c) 10:31:39:468 lpProfile->dwInternalFlags = 0x100

USERENV(598.59c) 10:31:39:468 RestoreUserProfile:  Leaving.

USERENV(598.59c) 10:31:39:468 UpgradeProfile: Entering

USERENV(598.59c) 10:31:39:468 UpgradeProfile: Build numbers match

USERENV(598.59c) 10:31:39:468 UpgradeProfile: Leaving Successfully

USERENV(598.59c) 10:31:39:468 Profile Ref Count is 1

USERENV(598.59c) 10:31:39:468 LoadUserProfile: Leaving critical Section.

USERENV(598.59c) 10:31:39:468 CSyncManager::LeaveLock 

USERENV(598.59c) 10:31:39:468 CSyncManager::LeaveLock: Lock released

USERENV(598.59c) 10:31:39:468 CHashTable::HashDelete: 
S-1-5-21-3061726268-1491933618-2623018998-10550 deleted

USERENV(598.59c) 10:31:39:468 CSyncManager::LeaveLock: Lock deleted

USERENV(598.59c) 10:31:39:468 LoadUserProfile: Impersonated user: 0000096c, 

USERENV(5d0.620) 10:31:39:750 ImpersonateUser: Failed to impersonate user with 

USERENV(5d0.620) 10:31:39:765 GetUserNameAndDomain Failed to impersonate user

USERENV(5d0.620) 10:31:39:781 ImpersonateUser: Failed to impersonate user with 

USERENV(5d0.620) 10:31:39:781 GetUserDNSDomainName: Failed to impersonate user

USERENV(5d0.620) 10:31:40:218 ImpersonateUser: Failed to impersonate user with 

USERENV(5d0.620) 10:31:40:218 GetUserNameAndDomain Failed to impersonate user

USERENV(5d0.620) 10:31:40:218 ImpersonateUser: Failed to impersonate user with 

USERENV(5d0.620) 10:31:40:218 GetUserDNSDomainName: Failed to impersonate user

USERENV(5d0.620) 10:31:40:468 ImpersonateUser: Failed to impersonate user with 

USERENV(5d0.620) 10:31:40:468 GetUserNameAndDomain Failed to impersonate user

USERENV(5d0.620) 10:31:40:468 ImpersonateUser: Failed to impersonate user with 

USERENV(5d0.620) 10:31:40:468 GetUserDNSDomainName: Failed to impersonate user

USERENV(598.59c) 10:31:40:468 LoadUserProfile: Reverted to user: 00000000

USERENV(598.59c) 10:31:40:468 LoadUserProfile: Leaving with a value of 1.

USERENV(598.59c) 10:31:40:468 

USERENV(598.59c) 10:31:40:468 LoadUserProfile: LoadUserProfileP succeeded

USERENV(598.59c) 10:31:40:468 LoadUserProfile:  Returning success.  Final 
Information follows:

USERENV(598.59c) 10:31:40:468 lpProfileInfo->UserName = <gdifarnecio>

USERENV(598.59c) 10:31:40:468 lpProfileInfo->lpProfilePath = <>

USERENV(598.59c) 10:31:40:468 lpProfileInfo->dwFlags = 0x0

USERENV(598.59c) 10:31:40:468 LoadUserProfile: Returning TRUE. hProfile = 

USERENV(4c8.1b8) 10:31:42:953 LibMain: Process Name:  

USERENV(598.59c) 10:31:46:015 IsSyncForegroundPolicyRefresh: Synchronous, 
Reason: NonCachedCredentials

USERENV(598.440) 10:31:46:015 IsSyncForegroundPolicyRefresh: Synchronous, 
Reason: NonCachedCredentials

USERENV(7e0.7c) 10:31:52:500 LibMain: Process Name:  C:\WINDOWS\system32\cmd.exe

USERENV(598.a0) 10:32:40:549 ProcessGPOs: network name is local

Disclaimer link. To see it, just click the link below, or copy and
paste it into your browser's address line.

Other related posts: