Troubleshooting Slow Logons via PowerShell
Guest post by Niron Koren, ControlUp CTO Team
Since we released ControlUp 4.1 we’ve received a lot of feedback regarding the Logon Duration monitoring feature.
One of the main requests was to better explain our “Logon Duration – Other” component (which included any delay not caused by Profile, GPO or the Desktop component) and provide an easy way to find the culprit for slow logons.
Based on this feedback we decided to write a PowerShell script that will enable any Citrix and Windows admin to troubleshoot a slow logon process without requiring any 3rd party tools. The same script can also be executed via the ControlUp Script-based Actions feature.
This post will describe how the script works, the major logon phases it covers, the script prerequisites and a short video showing how the script helps troubleshooting two slow logon scenarios.
Analyze_Logon_Duration.ps1 is a PowerShell script that displays all major sequential phases of the logon process and makes it easy to see which phase is slowing down the user logon. It is also possible to see if there is a delay between the end of one phase and the start of the next one.
Here is a screenshot of the script output showing the logon duration analysis for a user called cuupm logging on to a XenApp server:
Some notes on the script output:
- Logon Time –based on the most recent logon event found in the security log for the specified user (Event ID 4624 with logon type 2, 10 or 11)
- Logon Duration –calculation of the login time and the end time of the last logon phase (in this example – 10:15:47 – 10:16:57)
- Interim Delay –between the end of the previous phase and the start of the current phase (in this example there was a delay of 1.7 seconds between the end of the Network Providers phase and the start of the Citrix Profile Management phase)
- GP Scripts –output will show if Group Policy scripts were executed in synchronous or asynchronous mode
The following table summarizes the logon phases the script covers and the Windows events used for calculating the start and end time for each phase:
|Logon Phase Name||Logon Phase Description||Start Event||End Event|
|Network Providers||A Network Provider is a DLL that is responsible for a certain type of connection protocol1. On each logon Winlogon notifies these Network Providers so they can collect credentials and authenticate the user for their network2. Citrix PnSson is a common network provider found on XenApp and XenDesktop VM’s.||Log name: SecurityEvent Id: 4688 (mpnotify.exe start)||Log name: SecurityEvent Id: 4689(mpnotify.exe end)|
|Citrix Profile Management||During logon, Citrix UPM copies the users’ registry entries and files from the user store to the local profile folder. If a local profile cache exists, the two sets are synchronized3.||Log name: ApplicationEvent Id: 10(User X path to the user store is…)||Log name:User Profile Service Event Id: 1(Received user logon notification on session X.)|
|User Profile||During logon, the system loads the user’s profile, and then other system components configure the user’s environment according to the information in the profile4.||Log name:User Profile Service Event Id: 1(Received user logon notification on session X.)||Log name:User Profile Service Event Id: 2(Finished processing user logon notification on session X.)|
|Group Policy**See also a detailed Group Policy load time script.||Enforce the domain policy and settings for the user session, in the case of synchronous processing the user will not see their desktop at logon until user GP processing is completed5.||Log name: GroupPolicyEvent Id: 4001(Starting user logon Policy processing for X.)||Log name: GroupPolicyEvent Id: 8001(Completed user logon policy processing for X.)|
|GP Scripts||Running the logon scripts configured in the relevant GPO’s, in the case of synchronous logon scripts Windows Explorer does not start until the logon scripts have finished running6.||Log name: GroupPolicyEvent Id: 4018(Starting Logon script for X.)||Log name: GroupPolicyEvent Id: 5018(Completed Logon script for X.)|
|Pre-Shell (Userinit)||Winlogon runs Userinit.exe, which runs logon scripts, reestablishes network connections, and then starts Explorer.exe, the Windows user interface7. On RDSH sessions, Userinit.exe also executes the Appsetup8 entries such as cmstart.exe which in-turn calls wfshell.exe||Log name: SecurityEvent Id: 4688(userinit.exe start)||Log name: SecurityDesktop session:Event Id: 4688(explorer.exe start)Published Apps:Event Id: 4688
|Shell**Only available when running the script via ControlUp.||The interval between the beginning of desktop initialization and the time the desktop became available to the user, also includes the Active Setup9 Phase.||Log name: SecurityEvent Id: 4688(explorer.exe start)||ControlUp argument – “Desktop Load Time”|
The following are the script prerequisites:
- Enable the auditing of process tracking via GPO or local security policy (secpol.msc) on all relevant computers. This is required since some of the phases start and end events are determined by the creation or termination of a specific process.