Troubleshooting Slow Logons via PowerShell

Sagnik Datta

9 years ago

**Update as of Feb, 2016 is available now in link here**

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 3^rd 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.

Script Overview

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

Script download link

Logon Phases

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 protocol¹. On each logon Winlogon notifies these Network Providers so they can collect credentials and authenticate the user for their network². 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 synchronized³.	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 profile⁴.	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 completed⁵.	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 running⁶.	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 interface⁷. On RDSH sessions, Userinit.exe also executes the Appsetup⁸ 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 (icast.exe start)
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 Setup⁹ Phase.	Log name: SecurityEvent Id: 4688(explorer.exe start)	ControlUp argument – “Desktop Load Time”

Script Prerequisites

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.

Note – one customer encountered an issue where enabling auditing via a GPO didn’t apply to the target computers. The fix is described here – Microsoft KB921468.

In order to support “older” user sessions it is recommended to increase the Security log size to 50MB or 100MB.
Since the script queries the Security event log, local administrator privileges are required (https://technet.microsoft.com/en-us/library/cc775525(WS.10).Aspx).

Script Notes

Perform the following steps to execute the script via PowerShell:

Import the script to the shell using the ‘Import-Module’ function.

e.g. “Import-Module C:\Scripts\LogonDuration\Analyze_Logon_Duration.ps1”

After importing the module you can call the Get-LogonDurationAnalysis function from the shell, the function requires 2 parameters:
1. -UserName: <The name of the user we want to examine>
2. -UserDomain: <The name of the domain the user is member of>
3. Example – “Get-LogonDurationAnalysis -Username cudemo -UserDomain ControlUp”

Additional notes:

If multiple sessions exist for the same user on the same computer, the script will show data relevant for the most recent user session.
Group Policy events are not generated if a previous session is still running for the same user account.

Analyze_Logon_Duration.ps1 (download link)

Troubleshooting Slow Logons –Demo

The following video demo shows how the Analyze Logon Duration PowerShell script helps identify the root cause of a slow logon for two user sessions:

ControlUp – A member of the Citrix Ready community

With a bird’s-eye-view of your VDI environment, hypervisors to individual processes, ControlUp provides performance visibility and end-user experience metrics to easily detect, troubleshoot and remediate issues in real-time and within context. Proactively apply best practices through ControlUp Insights to measure system health and give you definitive answers for everyday IT questions.

Learn more about ControlUp in this Citrix Ready blog post: ControlUp 4.0 – New XenServer/vSphere Support and Enhanced IOPS Troubleshooting. Get a free 30-day trial – www.controlup.com.

References