Use PowerShell to Debug Slow GPO Processing

This blog provides an example of how we can use PowerShell to debug slow GPO processing.

I wrote it a couple of years ago when we needed to debug why some machines were taking so long to log in.  They were stuck on the “applying group policies” screen for far too long, so we wanted to generate a report that detailed how long each policy took to process.

This PowerShell script does exactly that.  It queries the event logs on remote machine(s) and writes a report to a local log file.  In this example you will need to change the $logPath and update the computer names in ("computer1","computer2").

cls

$runDateTime = (get-date -format dd-MM-yyyy_HH-mm-ss).ToString()
$logPath = "C:\Alkane\"

function Write-Log($logFile, $message) {

    write-host $message

    if (test-path $logPath) {        
        $message | Out-File -FilePath $logFile -Append
    } else {
        write-host "*Could not find path to write logs"
    }
}


function get-EventData($events) {
    $event = @($events)[@($events).count-1]
    if ($event -and $event.gettype().name -eq "EventLogRecord") {
        $nodes = ([xml]$event.toXML()).event.eventData.childnodes
        $hash = @{}; foreach($n in $nodes){$hash.$($n.name) = $n.'#text'}
        return new-object PsObject -Property $hash
    }
}


function Get-GPOSpeed{
    param([string]$computerName)

    $logFile = $logPath + $computerName + "_" + $runDateTime + ".log"
      
	Write-Log $logFile "Processing $computerName..."

	if (!(Test-Connection $computerName -Count 1 -Quiet)) {
		Write-Log $logFile "Cannot ping $computerName.  Skipping."
		return;
	}

	#find username of currently logged in user
	$explorer = Get-WmiObject -ComputerName $computerName -Class Win32_Process -Filter 'Name = "explorer.exe"' | select -First 1
	if ($explorer -eq $null) {
		Write-Log $logFile "There is no user logged in.  Script cannot continue."
		return;
	}
	
	$user = $explorer.GetOwner()
	$username = "$($user.Domain)\$($user.User)"

	Write-Log $logFile "Logged in user detected as $Username"

	# get the main logon event that includes the activity-Id:
	$log = "Microsoft-Windows-GroupPolicy/Operational"
	$xPath = "*[EventData[Data[@Name='PrincipalSamName'] and (Data='$Username')]] and *[System[(EventID='4001')]]"
	$logon = Get-WinEvent -ComputerName $computerName -logname $log -FilterXPath $xPath -MaxEvents 1 -ea 0

	if ($logon -eq $null) {
		Write-Log $logFile "Cannot find a login event (user keeps locking/unlocking as opposed to logging off/on?).  Script cannot continue."
		return;
	}

	$start = $logon.TimeCreated.ToUniversalTime().ToString('s')
	$id = $logon.ActivityId.Guid

	Write-Log $logFile "Activity filter for event viewer logs is $id"

	# get all logon-events related to this logon-process:
	$xPath = "*[System[TimeCreated[@SystemTime >= '$start'] and Correlation[@ActivityID='{$id}']]]"
	$logonEvents = Get-WinEvent -ComputerName $computerName -logname $log -FilterXPath $xPath -ea 0

	# completeUserLogonPolicy:
	$completeUserLogonPolicy = get-EventData $logonEvents.where({$_.id -eq 8001})
	$completeUserLogonPolicyDuration = $completeUserLogonPolicy.PolicyElaspedTimeInSeconds

	# get the exact logon duration:
	$logonEndData = get-EventData $logonEvents.where({$_.id -eq 5117})
	$duration = $logonEndData.SessionTimeElapsedInMilliseconds
	$duration = ([TimeSpan]::FromMilliseconds($duration)).TotalSeconds

	# discovery time for the closest domain controller:
	$dcSelectData = get-EventData $logonEvents.where({$_.id -eq 5326})
	$dcDiscoveryTime = $dcSelectData.DCDiscoveryTimeInMilliSeconds
	$dcDiscoveryTime = ([TimeSpan]::FromMilliseconds($dcDiscoveryTime)).TotalSeconds

	# domain controller details:
	$dcData = get-EventData $logonEvents.where({$_.id -eq 5308})
	$dcName = $dcData.DCName
	$dcIp = $dcData.DCIPAddress
	
	# network speed to DC:
	$dcNetData = get-EventData $logonEvents.where({$_.id -eq 5314})
	$dcSpeed = $dcNetData.BandwidthInkbps
	$isSlowLink = $dcNetData.IsSlowLink

	# logon breakdown by CSE-type:
	$cseEndEvents = $logonEvents.where({$_.id -eq 5016})
	$cseData = foreach($e in $cseEndEvents) {
	$data = get-EventData $e
		New-Object PsObject -Property @{
			time = $e.TimeCreated
			name = $data.CSEExtensionName
			duration = ([TimeSpan]::FromMilliseconds([int]$data.CSEElaspedTimeInMilliSeconds)).TotalSeconds
		}
	}

	# logon breakdown by GPOs:
	$gpoEndEvents = $logonEvents.where({$_.id -eq 4016})
	$gpoData = foreach($e in $gpoEndEvents) {
		$data = get-EventData $e
		$gpolistdata = get-EventData $data.ApplicableGPOList
		$gpoXml = [xml]"<GPOs>$($data.ApplicableGPOList)</GPOs>"
		$gpoList = $gpoXml.GPOs.GPO | select name, id -Unique
		$gpoList = $gpoList | sort name
		foreach ($g in $gpoList) {
			 New-Object PsObject -Property @{
				time = $e.TimeCreated
				ext = $data.CSEExtensionName
				gpo = $g.Name
			}
		}
	}

	# GPO network speed:
	$gpoNetData = get-EventData $logonEvents.where({$_.id -eq 5327})
	$gpoSpeed = $gpoNetData.NetworkBandwidthInKbps

	# list of all GPOs (use this to get the count for now, since this bit doesnt contain timings)
	$gpoListEvent = get-EventData $logonEvents.where({$_.id -eq 5312})
	$gpoXml = [xml]"<GPOs>$($gpoListEvent.GPOInfoList)</GPOs>"
	$gpoList = $gpoXml.GPOs.GPO | select name, id -Unique
	$gpoList = $gpoList | sort name
	$gpoCount = @($gpoList).count

	# number of error-events:
	$errCount = 0
	$errMessage = ""
	foreach($e in $logonEvents) {
		$data = get-EventData $e
		$errorCode = $data.ErrorCode
		$errorMess = $data.CSEExtensionName

		if ($errorCode -gt 0) {
			$errCount += 1
			$errMessage += "$($e.TimeCreated.ToString('dd/MM/yyyy HH:mm:ss')) - $errorMess - $(&net helpmsg $errorCode)"
		}
	}


	Write-Log $logFile "User logon data for $username is as follows:"
	Write-Log $logFile "Logon Duration: $completeUserLogonPolicyDuration seconds"
	Write-Log $logFile "Logon Time: $($logon.TimeCreated.ToString('dd/MM/yyyy HH:mm:ss'))"
	Write-Log $logFile "Exact Login Duration: $duration seconds"
	Write-Log $logFile "Error Count: $errCount"
	Write-Log $logFile "Error Text: $errMessage"
	Write-Log $logFile "DC Search Time: $dcDiscoveryTime seconds"
	Write-Log $logFile "DC Name: $dcName"
	Write-Log $logFile "DC IP Address: $dcIp"
	Write-Log $logFile "DC Connection Speed: $dcSpeed kbps"
	Write-Log $logFile "DC Slow Link: $isSlowLink"
	Write-Log $logFile "GPO Connection Speed: $gpoSpeed kbps"
	Write-Log $logFile "Unique GPO Count: $gpoCount"

	$cseData | sort time | foreach {
		$cseTime = $_.time
		$cseName = $_.name
		$cseDuration = "$($_.duration) seconds"

		Write-Log $logFile "$cseTime - $cseName - $cseDuration"
		$gpoData | sort time | foreach {
			$gpoTime = $_.time
			$gpoExt = $_.ext
			$gpoName = $_.gpo
			if ($cseName -eq $gpoExt) {
				Write-Log $logFile "    $gpoName"
			}
		}
	}    
}

#add computer names here
foreach ($computerName in  ("computer1","computer2")) {
    Get-GPOSpeed $computerName
}