First published on TechNet on Sep 03, 2018
Hello all, Nathan Penn back again to cover one of the more frequently brought up topics: System bootup and user logon performance – Specifically "Is group policy slowing me down in my environment?"
Luckily, if we know where to look we can get right to that answer quickly. To start, let's clarify a couple of semantics so that we are all on the same page. For our purpose, boot time is how long it takes for the computer to load the Windows Operating System from power on, or Reboot, and get to the Interactive logon screen (Ctrl + Alt + Del / Windows Hello).
Logon time is how long it takes, after a user initiates the interactive logon with appropriate credentials/biometrics, to present the desktop and applications for use.
With that out of the way, lets jump into how we can identify if Group Policy is causing delays...
Off to the Windows Event Logs. First stop is the Windows System log. Here we can find Event ID 12 from the Kernel-General source, that details the system start time following a power on or reboot.
Scrolling up from the Event ID 12 we will notice several Event ID 7036 from Service Control Manager source. Contained within one of the 7036 events will be an entry with the following description "The Group Policy Client service entered the running state."
In this instance, the computer started at 1:51:12 and the Group Policy Client service started at 1:51:25, or 13 seconds later. Group Policy has had no effect on the boot time, but now things are about to change.
To see what affect Group Policy has on system boot time, we need to move to the Group Policy Operational log found in the Event Viewer under Applications and Services -> Microsoft -> Windows -> Group Policy -> Operational.
In the Group Policy Operational log if we go to the time of the Group Policy Client service starting we will find several 5320 Event IDs, one of which will have the Description "Initializing and reading current service configuration for the Group Policy Client service."
Now we know the system is powering up and starting services, the Group Policy Client service has started, and Group Policy Client service has initialized its startup configuration, and we are ready to begin processing some GPOs.
To simplify things a bit here are the four primary events contained in the Group Policy Operational log that I am sure everyone is most interested in, but we will also walk through some of the other important ones further below:
- Event ID 4000 - Starting computer boot policy processing
- Event ID 8000 - Completed computer boot policy processing for XXX in # seconds.
- Event ID 4001 - Starting user logon policy processing
- Event ID 8001 - Completed user logon policy processing for XXX in # seconds.
With these events, we can see exactly when both computer and user policy processing started, finished, as well as how long it took for each. I'm sure you are all thinking that is fantastic by itself, right.. But what if we want a little more detail, like why did it take X number of seconds? That's where the events in between matter, so let's walk through a few of the important ones and the details provided. Following the Event ID 4000 (Starting computer boot policy processing) and 4001 (Starting user logon policy processing) we need to identify where the associated computer or user objects are located in the Active Directory (AD) structure to determine which policies will be applied. This system call to a Domain Controller (DC) is captured in an Event ID 5017 that also details how long it took.
The next thing that needs to happen is to discover and connect to a DC that we can use to perform the Group Policy requests against. Event ID 5326 captures this and defines the time it took to make that connection.
Moving from there we have an Event ID 5310 that details what we have found and will be using, from the location of the computer or user object in AD as well as the DC it will be using for the GPO requests.
A look at the following Event ID 5312 shows a list of all policies that apply to the computer or user object based on its AD placement.
Event ID 5313 will show if any policies have been filtered out as not applicable due to a security filter (i.e. A policy that is targeted to a specific list or group of computer or user objects).
As you can see there are several events that can give a clear picture if Group Policy is causing delays by reviewing the Group Policy Operational log. There are many, many more entries contained in the Group Policy Operational log that I didn't have time to cover in this post, that can determine how long a policy took to process, to logon/startup script execution time, as well as system timeouts.
Hopefully, this helps and removes some of the mystery of whether Group Policy is slowing you down.
Thanks for reading everyone!