SharePoint logs every `SPMonitoredScope` as a pair: ``` Entering Monitored Scope (Request (GET:http://...)) Leaving Monitored Scope (Request (GET:http://...)). Execution time=4523.45 ``` The trap is to just regex all `Execution time=` numbers. You lose: 1. **which scope** it belongs to - `Request` vs `GetWebPartPageContent` vs `SQL Query` vs `Timer Job` 2. **which request** it belongs to - two concurrent requests interleave in the same .log The key in ULS is columns 2,3,9: `Process + TID + CorrelationId`. The `CorrelationId` is the same for a whole request. You must never sum / compare `Execution time` across different CorrelationIds or Processes. This script parses raw `.log` files streaming - no SharePoint snapin needed - and preserves that linkage: ```powershell <# .SYNOPSIS Extract SharePoint ULS performance threshold / Monitored Scope data. .DESCRIPTION Parses ULS .log files for: Leaving Monitored Scope (...). Execution time=... and matches each Execution time to: 1. Its correct Scope name 2. Its same Request/Process via CorrelationId + ProcessName/ProcessId Outputs slowest scopes, summary by Scope name, and summary by Request (Correlation). ULS columns (tab delimited, 9 cols): Timestamp | Process | TID | Area | Category | EventID | Level | Message | Correlation Example Message: Leaving Monitored Scope (Request (GET:http://intranet/pages/home.aspx)). Execution time=4523.4567 Leaving Monitored Scope (GetWebPartPageContent). Execution time=14.20 Leaving Monitored Scope (Timer Job job-schedule). Execution time=2100.1 .PARAMETER LogPath File or folder. Folder parses *.log recursively. .PARAMETER ThresholdMilliseconds Only report scopes with ExecutionTime >= this. Default 1000ms. .PARAMETER Top How many slowest to display. Default 20. .PARAMETER ExportCsvPath Optional full path to export all threshold violations to CSV. .EXAMPLE .\Get-ULSPerformanceThreshold.ps1 -LogPath C:\Logs\SPServer-20260915.log -ThresholdMilliseconds 2000 .EXAMPLE .\Get-ULSPerformanceThreshold.ps1 -LogPath C:\ULSLogs -ThresholdMilliseconds 1000 -ExportCsvPath C:\Temp\Slow.csv -Top 50 #> [CmdletBinding()] param( [Parameter(Mandatory=$true)] [string[]]$LogPath, [double]$ThresholdMilliseconds = 1000, [int]$Top = 20, [string]$ExportCsvPath ) Set-StrictMode -Version Latest # 1. Leaving ... ONLY - Entering has no Execution time. # Greedy (.*) is intentional: Scope itself contains ( ) e.g. Request (GET:http://...) # We want up to the LAST "). Execution time=" $LeavingRegex = [regex]'Leaving Monitored Scope $(?.*)$\.\s*Execution time=(?\d+(\.\d+)?)' $ProcessRegex = [regex]'^(?.+?)\s*$(?0x[0-9A-Fa-f]+|\d+)$\s*$' $RequestScopeRegex = [regex]'^Request $(?[A-Z]+):(?.*)$$' $TimerScopeRegex = [regex]'^Timer Job $(?.*)$$' function Resolve-LogFiles { param([string[]]$Paths) $files = @() foreach($p in $Paths){ if(Test-Path $p -PathType Container){ $files += Get-ChildItem -Path $p -Filter *.log -File -Recurse -ErrorAction SilentlyContinue } elseif(Test-Path $p){ $files += Get-Item $p } else { # wildcard support $files += Get-ChildItem -Path $p -File -ErrorAction SilentlyContinue } } return $files | Sort-Object FullName -Unique } function Parse-ULSLine { param( [string]$Line, [string]$ServerName ) # Fast pre-filter before expensive split/regex if($Line.IndexOf('Leaving Monitored Scope', [StringComparison]::OrdinalIgnoreCase) -lt 0){ return $null } if($Line.IndexOf('Execution time=', [StringComparison]::OrdinalIgnoreCase) -lt 0){ return $null } # Split into max 9 fields - Message itself may contain tabs, keep remainder in field 9 $f = $Line -split "`t",9 if($f.Count -ne 9){ return $null } $timestampStr = $f[0].Trim() $processField = $f[1].Trim() $tidField = $f[2].Trim() # $f[3]=Area $f[4]=Category $f[5]=EventID $f[6]=Level $area = $f[3].Trim() $category = $f[4].Trim() $level = $f[6].Trim() $message = $f[7].Trim() $correlation = $f[8].Trim() $m = $LeavingRegex.Match($message) if(-not $m.Success){ return $null } # Execution time not from a Leaving scope -> ignore $scopeName = $m.Groups['Scope'].Value.Trim() $execStr = $m.Groups['ExecTime'].Value [double]$execMs = 0 if(-not [double]::TryParse($execStr, [ref]$execMs)){ return $null } [datetime]$ts = [datetime]::MinValue [datetime]::TryParse($timestampStr, [ref]$ts) | Out-Null # Process: "w3wp.exe (0x3A84)" -> Name + Pid $procName = $processField $procId = $processField $pm = $ProcessRegex.Match($processField) if($pm.Success){ $procName = $pm.Groups['Name'].Value $procId = $pm.Groups['Pid'].Value } # Classify scope so Request total is not confused with child scopes $scopeType = 'Other' $url = $null $httpMethod = $null $timerJob = $null $rm = $RequestScopeRegex.Match($scopeName) $tm = $TimerScopeRegex.Match($scopeName) if($rm.Success){ $scopeType = 'Request' $httpMethod = $rm.Groups['Method'].Value $url = $rm.Groups['Url'].Value } elseif($tm.Success){ $scopeType = 'TimerJob' $timerJob = $tm.Groups['Job'].Value } elseif($scopeName -like 'Request *'){ $scopeType = 'Request' } # Normalize empty correlation (000... or empty) -> cannot safely group by request if([string]::IsNullOrWhiteSpace($correlation) -or $correlation -eq '00000000-0000-0000-0000-000000000000'){ $correlation = '00000000-0000-0000-0000-000000000000' } [pscustomobject]@{ Timestamp = $ts Server = $ServerName ProcessName = $procName ProcessId = $procId ThreadId = $tidField CorrelationId = $correlation Area = $area Category = $category Level = $level Scope = $scopeName ScopeType = $scopeType HttpMethod = $httpMethod Url = $url TimerJobName = $timerJob ExecutionTimeMs = $execMs Message = $message } } $logFiles = Resolve-LogFiles -Paths $LogPath if(-not $logFiles -or $logFiles.Count -eq 0){ Write-Error "No .log files found in $LogPath" return } Write-Verbose "Found $($logFiles.Count) log file(s)" $allScopes = New-Object System.Collections.Generic.List[object] $totalLines = 0 foreach($file in $logFiles){ # Server name is first token of ULS filename: SERVER-20260915-xxxx.log $server = ($file.BaseName -split '-')[0] if([string]::IsNullOrWhiteSpace($server)){ $server = $env:COMPUTERNAME } Write-Progress -Activity "Parsing ULS" -Status $file.Name -PercentComplete 0 $lineNo = 0 try{ $reader = New-Object System.IO.StreamReader($file.FullName, $true) while($null -ne ($line = $reader.ReadLine())){ $lineNo++; $totalLines++ $obj = Parse-ULSLine -Line $line -ServerName $server if($null -ne $obj){ $allScopes.Add($obj) } if(($lineNo % 50000) -eq 0){ Write-Progress -Activity "Parsing $($file.Name)" -Status "$lineNo lines, $($allScopes.Count) scopes" -PercentComplete -1 } } } finally { if($reader){ $reader.Close(); $reader.Dispose() } } Write-Verbose "$($file.Name): $lineNo lines scanned" } Write-Progress -Activity "Parsing ULS" -Completed if($allScopes.Count -eq 0){ Write-Warning "Scanned $totalLines lines, found 0 'Leaving Monitored Scope ... Execution time=' entries." return } # Filter to threshold - this is the performance violation set $violations = $allScopes | Where-Object { $_.ExecutionTimeMs -ge $ThresholdMilliseconds } | Sort-Object ExecutionTimeMs -Descending Write-Host "" Write-Host "=== ULS Performance Threshold Report ===" -ForegroundColor Cyan Write-Host "Files scanned : $($logFiles.Count)" Write-Host "Lines scanned : $totalLines" Write-Host "Monitored scopes : $($allScopes.Count)" Write-Host "Exceeding >= $ThresholdMilliseconds ms : $($violations.Count)" Write-Host "" if($violations.Count -eq 0){ Write-Host "No scopes exceeded threshold." -ForegroundColor Green return } # 1. Top N slowest - useful actionable list Write-Host "--- TOP $Top SLOWEST SCOPES (each ExecutionTime belongs to its own Scope + Correlation) ---" -ForegroundColor Yellow $violations | Select-Object -First $Top | Format-Table Timestamp, Server, CorrelationId, ProcessName, ScopeType, ExecutionTimeMs, @{N='Scope/Url';E={if($_.ScopeType -eq 'Request'){"$($_.HttpMethod) $($_.Url)"} elseif($_.ScopeType -eq 'TimerJob'){$_.TimerJobName} else{$_.Scope}}} -AutoSize | Out-String | Write-Host # 2. Summary by Scope name - what code path is slow? Write-Host "--- SUMMARY BY SCOPE NAME ---" -ForegroundColor Yellow $violations | Group-Object Scope | ForEach-Object { $times = $_.Group | Select-Object -ExpandProperty ExecutionTimeMs [pscustomobject]@{ Count = $_.Count AvgMs = [math]::Round(($times | Measure-Object -Average).Average,2) MaxMs = [math]::Round(($times | Measure-Object -Maximum).Maximum,2) TotalMs = [math]::Round(($times | Measure-Object -Sum).Sum,2) Scope = $_.Name } } | Sort-Object MaxMs -Descending | Select-Object -First $Top | Format-Table Count, AvgMs, MaxMs, TotalMs, Scope -AutoSize | Out-String | Write-Host # 3. Summary by Request - CRITICAL: group by CorrelationId + ProcessName, never mix requests # The Request scope ExecutionTime is the total. Child scopes with same Correlation are breakdown. Write-Host "--- SLOWEST REQUESTS BY CORRELATION (matched to same request/process) ---" -ForegroundColor Yellow $requestTotals = $violations | Where-Object { $_.ScopeType -eq 'Request' } if($requestTotals.Count -gt 0){ $requestTotals | Select-Object -First $Top | ForEach-Object { $req = $_ # Find ALL scopes (even under threshold) for this exact request/process $related = $allScopes | Where-Object { $_.CorrelationId -eq $req.CorrelationId -and $_.ProcessName -eq $req.ProcessName } $childSlow = ($related | Where-Object { $_.ScopeType -ne 'Request' -and $_.ExecutionTimeMs -ge $ThresholdMilliseconds } | Measure-Object).Count [pscustomobject]@{ Timestamp = $req.Timestamp CorrelationId = $req.CorrelationId Process = "$($req.ProcessName)$($req.ProcessId)" TotalMs = [math]::Round($req.ExecutionTimeMs,2) ChildScopesOverThreshold = $childSlow TotalScopesInRequest = ($related | Measure-Object).Count Method = $req.HttpMethod Url = $req.Url } } | Format-Table Timestamp, TotalMs, ChildScopesOverThreshold, CorrelationId, Method, Url -AutoSize | Out-String | Write-Host Write-Host "Tip: drill into one request with: Merge-SPLogFile -Path C:\Temp\req.log -Correlation -Overwrite" -ForegroundColor Gray } else { Write-Host "No top-level Request scopes over threshold. Slowest are nested scopes / Timer Jobs:" $violations | Group-Object -Property CorrelationId,ProcessName | ForEach-Object { $max = ($_.Group | Measure-Object ExecutionTimeMs -Maximum).Maximum [pscustomobject]@{ CorrelationId = ($_.Group[0].CorrelationId) Process = ($_.Group[0].ProcessName) Count = $_.Count MaxMs = [math]::Round($max,2) } } | Sort-Object MaxMs -Descending | Select-Object -First $Top | Format-Table CorrelationId, Process, Count, MaxMs -AutoSize | Out-String | Write-Host } # 4. Distribution by Process - w3wp vs OWSTIMER vs others Write-Host "--- DISTRIBUTION BY PROCESS ---" -ForegroundColor Yellow $violations | Group-Object ProcessName | Select-Object Name, Count, @{N='AvgMs';E={[math]::Round((($_.Group|Measure-Object ExecutionTimeMs -Average).Average),2)}}, @{N='MaxMs';E={[math]::Round((($_.Group|Measure-Object ExecutionTimeMs -Maximum).Maximum),2)}} | Sort-Object Count -Descending | Format-Table -AutoSize | Out-String | Write-Host if($ExportCsvPath){ try{ $dir = Split-Path $ExportCsvPath -Parent if($dir -and -not (Test-Path $dir)){ New-Item -ItemType Directory -Path $dir -Force | Out-Null } $violations | Select-Object Timestamp,Server,CorrelationId,ProcessName,ProcessId,ThreadId, ScopeType,HttpMethod,Url,TimerJobName,Scope,ExecutionTimeMs,Level,Area,Category | Export-Csv -Path $ExportCsvPath -NoTypeInformation -Encoding UTF8 -Force Write-Host "Exported $($violations.Count) rows to $ExportCsvPath" -ForegroundColor Green } catch { Write-Error "CSV export failed: $_" } } # Return objects for further piping $violations ``` **Why this is correct:** * `Leaving Monitored Scope (...)` regex only - `Entering` lines are ignored, so an `Execution time` can never be attributed to the wrong start. * Greedy `.*` up to the last `). Execution` correctly keeps `Request (GET:http://...)` together as one scope. * `ScopeType` separates totals (`Request`) from parts (SQL, WebPart, etc.). You don't sum children to get the total. * Every grouping for a request uses `Where CorrelationId -eq ... -and ProcessName -eq ...`. Two concurrent requests with different GUIDs are never mixed, even if they hit the same URL at the same millisecond. Empty GUIDs (`000...`) fall back to process-level grouping with a warning that they can't be request-correlated. **Useful output you get:** 1. Top N slowest individual scopes with Timestamp/Server/Correlation/URL/Time 2. Summary by Scope name - Avg/Max/Count to find hot code paths 3. Slowest Requests by Correlation - total request time + how many child scopes also violated, so you can run `Merge-SPLogFile -Correlation ` next 4. Distribution by Process - tells you if it's `w3wp.exe` (web) vs `owstimer.exe` (timer job) Run e.g.: ```powershell .\Get-ULSPerformanceThreshold.ps1 -LogPath "C:\Program Files\Common Files\Microsoft Shared\Web Server Extensions\16\LOGS" -ThresholdMilliseconds 3000 -ExportCsvPath C:\Temp\SlowScopes.csv ```

SP ULS