This post continues the series that started here.
Today I’ll be discussing the Winlogon phase. A lot of activity takes place during Winlogon and it’s common to see delays here. Additionally, the interplay between activities provides an opportunity for complication so I’ll be highlighting important considerations for analysis.
Some of the activities that occur during the Winlogon phase have a dependency on supporting network and server infrastructure. I’ll write a post regarding the influence of your infrastructure at a later time.
Boot Phase Winlogon – Phase Activity
- Service Control Manager launches services
- Machine Group Policy is applied and start-up scripts are executed
- Logon Screen is displayed and a user logs in
- User Group Policy is applied and logon scripts are executed
- User profile loads and network drives are mapped
- Explorer is started
Boot Phase Winlogon – Measurement
As with the previous two phases, a summary XML file generated from a boot trace using xperf.exe displays the phase duration as WinlogonInit –
Alternatively, the Regions of Interest graph (discussed in Post 11) shows this phase duration as Boot-Winlogon-Phase:
Boot Phase Winlogon – Potential Issues
As you might imagine, there’s a reasonable degree of complexity here.
Let’s begin with Services –
- Disk contention may impact service start times
- All services configured for auto-start are started as soon as possible
- Grouped auto-start services block the next group until they all start
- Ungrouped auto-start services wait for auto-start groups
- Demand-start and delayed-auto-start services wait on auto-start services
You can envision service start as follows (again, thank you Matthew Reynolds for this conceptualization) –
In addition, consider –
- The Network List Service is demand-start
- If Group Policy processing is synchronous, it will wait for the Network List Service
- i.e. it waits for all auto-start services
Moving on to Group Policy –
- Synchronous processing waits for the network which waits for auto-start services
- Triggers for synchronous processing
- Always wait for the network at computer startup and logon policy setting
- Folder Redirection
- Roaming User Profiles
- Software Installation (via policy)
- Home Drives
Consider also that –
- Excessive numbers of GPOs increases processing time
- Fewer GPOs each with more settings are generally processed more quickly than more GPOs with fewer settings
- Start-up and logon scripts add time
- Especially true when processed synchronously
- PowerShell scripts trigger loading of .Net libraries before they can process
- WMI and Security filtering impacts processing time
- WMI is often very expensive
And lastly, User Profiles –
- Local user profiles are generally fast to load
- Large roaming user profiles may introduce delays
- Heavy dependency on network and server infrastructure
Boot Phase Winlogon – Remediation
After examining CPU and Disk utilization, the first avenue of investigation is to expand Boot-Winlogon-Phase: in the Regions of Interest graph. By doing so, we see a breakdown of activities with the Winlogon phase –
The example above provides some insight that the User Profile has loaded quickly but Group Policy is a contributing factor, both during machine policy processing as well as user policy processing. With this information, I’ll want to check whether policy processing is in synchronous mode.
To do this, I’ll select and zoom to Boot-Winlogon-Phase:, open the Generic Events table, order columns as follows and then expand the Microsoft-Windows-GroupPolicy provider –
Now that I know synchronous processing of Group Policy is taking place, I will also examine the Services graph and table. Once again, column ordering is important –
Now I’ve identified a slow starting service, I would investigate whether it may be moved to delayed-auto-start and seek an update from the vendor.
If I move back to the Generic Events table (using exactly the same layout as above), scrolling further down reveals two rows. The first row represents the Group Policy Objects that have applied while the second row represents the Group Policy Objects that have been filtered. These rows are a little hard to find but Field 1 contains useful information that shows up in a tool tip when you mouse over it.
Applied GPOs (machine) –
Filtered GPOs (machine) –
I see that C-GPO1 and C-GPO3 are not applied due to a WMI filter. WMI filtering may be a very expensive operation so my next avenue of investigation would be to examine those filters and attempt to exclude those Group Policy objects using another method.
Similarly, when I scroll down further still, the Generic Events table shows applied and filtered Group Policy Objects for the user –
Applied GPOs (user) –
Filtered GPOs (user) –
Here, no Group Policy Objects are applied to the user and several are filtered using WMI. In addition, I can see that some of them were also applicable to the computer which may be an indication that Group Policy loopback mode is in use. These are facts I can use to look for Group Policy optimizations.
Lastly, after zooming to Boot-Winlogon-Phase:, I can use the Process Lifetimes graph and table to identify processes that may have been launched by start-up or logon scripts –
Transient processes whose life ends within GPClient phases (computer or user) may provide clues regarding script execution delaying the user experience. Consider script optimization or moving script functionality to Group Policy Preferences (where possible).
Winlogon is a complex phase with a lot going on. Windows Performance Analyzer (WPA) provides useful insight into the phase activities and makes it easier to isolate problems. As you’ll find, it takes some time and experience to become familiar with the workflow I’ve described but with practice, analysis with these tools is powerful and specific.