Skip to content

perf(logs): filters before the entry is built, one expression for the event table #18

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
fadwen merged 1 commit into from
Oct 6, 2026
Merged

perf(logs): filters before the entry is built, one expression for the event table #18

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions CHANGELOG.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -65,6 +65,12 @@ release notes.
detection, 60 scripts in 5.4 s against 14.0 s. Every rule walked the syntax tree itself, some once per
command name they look for; the tree is now walked once per script and the nodes indexed by type and
the commands by name, and the rules read the index. Findings are unchanged.
- `Get-IntuneAgentLog` and `Get-IntuneAgentTimeline` read a large log in a fraction of the time. On a 15 MB
agent log of 80,000 entries: every entry in 30 s against 62 s; the entries of one policy, by `-Id`, in
5 s against 25 s; `-EventName` with `-Last` in 12 s against 90 s; a timeline by id in 5 s against 26 s.
The filters now run on the raw record before an entry is built, which was most of an entry's cost; the
44 event patterns are one expression matched once per message instead of 44 statements; a rolled-over
file last written before `-After` is not read at all. Results are unchanged.
## [0.27.0] - 2026-10-05

Fixes to the runtime harness and to four rules, each rule change backed by a tenth validation
Expand Down
124 changes: 106 additions & 18 deletions Private/ConvertFrom-IslCmTraceLog.ps1
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,19 +15,62 @@ function ConvertFrom-IslCmTraceLog {
Message, Log (the file's base name) and Line (the line the entry starts on). Event, Detail
and Id are left empty for Get-IntuneAgentLog to fill.

The filters are the ones Get-IntuneAgentLog offers, applied to the raw record before an
object is built for it. Building the object is most of what an entry costs, so a filtered
read of a 22 MB log takes seconds where building every entry takes a minute.

.PARAMETER Path
The log file to parse.

.PARAMETER Level
Keep entries of these levels only: Information, Warning, Error.

.PARAMETER After
Keep entries at or after this local time.

.PARAMETER Before
Keep entries before this local time.

.PARAMETER Pattern
Keep entries whose message matches this regular expression, case-insensitive like -match.

.PARAMETER Id
Keep entries whose message contains any of these strings, case-insensitive; a policy or
app id, usually.

.PARAMETER Contains
Keep entries whose message contains any of these strings, case-sensitive. Get-IntuneAgentLog
passes the literal text the wanted events' patterns start with, so a message that can match
none of them is dropped before the pattern runs.

.EXAMPLE
ConvertFrom-IslCmTraceLog -Path 'C:\ProgramData\Microsoft\IntuneManagementExtension\Logs\HealthScripts.log'

Every entry of the remediation log as objects.

.EXAMPLE
ConvertFrom-IslCmTraceLog -Path .\AppWorkload.log -Id 9b6543c3-6d66-4cfb-a8fb-d780079278f6 -Level Error

The error entries that mention the app, without building the others.
#>
[CmdletBinding()]
[OutputType('IntuneScriptLab.AgentLogEntry')]
param(
[Parameter(Mandatory)]
[string]$Path
[string]$Path,

[ValidateSet('Information', 'Warning', 'Error')]
[string[]]$Level,

[datetime]$After,

[datetime]$Before,

[string]$Pattern,

[string[]]$Id,

[string[]]$Contains
)

$file = (Resolve-Path -LiteralPath $Path -ErrorAction Stop).ProviderPath
Expand All @@ -42,38 +85,83 @@ function ConvertFrom-IslCmTraceLog {
}

$levels = @{ '1' = 'Information'; '2' = 'Warning'; '3' = 'Error' }
$wantedTypes = if ($Level) { @($levels.Keys | Where-Object { $levels[$_] -in $Level }) } else { $null }
$hasAfter = $PSBoundParameters.ContainsKey('After')
$hasBefore = $PSBoundParameters.ContainsKey('Before')
$ordinalIgnoreCase = [System.StringComparison]::OrdinalIgnoreCase
$ordinal = [System.StringComparison]::Ordinal

# An agent log of 22 MB is 80,000 entries, and every statement here runs once per entry. The
# attributes come out of one compiled regex in the order the agent writes them, the timestamp
# is read the way ConvertTo-IslCmTraceTime reads it without the call, and the filters run on
# the raw strings before anything is built. Lines are counted only up to an entry that is kept
$attributeRegex = $script:IslCmTraceAttributeRegex
$timeFormat = $script:IslCmTraceTimeFormat
$invariant = [cultureinfo]::InvariantCulture
$noStyle = [System.Globalization.DateTimeStyles]::None
$biasChars = [char[]]@('+', '-')
$logName = [System.IO.Path]::GetFileNameWithoutExtension($file)
$entryPattern = '<!\[LOG\[(?<message>.*?)\]LOG\]!><time="(?<time>[^"]*)" date="(?<date>[^"]*)"' +
'(?<attributes>[^>]*)>'
$entryRegex = [regex]::new($entryPattern, [System.Text.RegularExpressions.RegexOptions]::Singleline)
$line = 1
$scanned = 0
$counted = 0
foreach ($match in $entryRegex.Matches($text)) {
# Line numbers accumulate as the matches advance, so the text is scanned once
while ($true) {
$newline = $text.IndexOf("`n", $scanned, $match.Index - $scanned)
if ($newline -lt 0) { break }
$line++
$scanned = $newline + 1
$groups = $match.Groups
$attributeMatch = $attributeRegex.Match($groups['attributes'].Value)
$type = if ($attributeMatch.Success) { $attributeMatch.Groups[2].Value } else { '1' }
if ($wantedTypes -and $type -notin $wantedTypes) { continue }

$message = $groups['message'].Value
if ($Pattern -and $message -notmatch $Pattern) { continue }

@fadwen fadwen Oct 6, 2026

Copy link
Copy Markdown
Owner Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The -match operator on purpose, not a cached regex: Get-IntuneAgentLog applied -Pattern with -notmatch, which is case-insensitive, and a Regex object would be case-sensitive unless told otherwise. Same result as before for every pattern.

if ($Id) {
$mentioned = $false
foreach ($value in $Id) {
if ($message.IndexOf($value, $ordinalIgnoreCase) -ge 0) { $mentioned = $true; break }
}
if (-not $mentioned) { continue }
}
if ($Contains) {
$present = $false
foreach ($value in $Contains) {
if ($message.IndexOf($value, $ordinal) -ge 0) { $present = $true; break }
}
if (-not $present) { continue }
}

$timeText = $groups['time'].Value
$bias = $timeText.IndexOfAny($biasChars, [Math]::Min(7, $timeText.Length))
if ($bias -ge 0) { $timeText = $timeText.Substring(0, $bias) }
$time = [datetime]::MinValue
$stamp = "$($groups['date'].Value) $timeText"
if (-not [datetime]::TryParseExact($stamp, $timeFormat, $invariant, $noStyle, [ref]$time)) {
throw "Not a CMTrace timestamp: $stamp ($file)"
}
if ($hasAfter -and $time -lt $After) { continue }
if ($hasBefore -and $time -ge $Before) { continue }

# The newlines between the last kept entry and this one, in one .NET call
if ($match.Index -gt $counted) {
$line += $text.Substring($counted, $match.Index - $counted).Split("`n").Length - 1

@fadwen fadwen Oct 6, 2026

Copy link
Copy Markdown
Owner Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Lines are counted lazily so a skipped entry costs nothing here; the gap can span many skipped records, so it is one Substring and Split rather than an IndexOf loop, which ran once per newline in PowerShell (3 s of the 80,000-entry read).

$counted = $match.Index
}
$scanned = $match.Index
$attributes = $match.Groups['attributes'].Value
$component = if ($attributes -match 'component="([^"]*)"') { $Matches[1] } else { '' }
$type = if ($attributes -match 'type="(\d)"') { $Matches[1] } else { '1' }
$thread = if ($attributes -match 'thread="(\d+)"') { [int]$Matches[1] } else { $null }
$timeSplat = @{ Time = $match.Groups['time'].Value; Date = $match.Groups['date'].Value }
[pscustomobject]@{
PSTypeName = 'IntuneScriptLab.AgentLogEntry'
Time = ConvertTo-IslCmTraceTime @timeSplat
Time = $time
Level = if ($levels.ContainsKey($type)) { $levels[$type] } else { 'Information' }
Component = $component
Thread = $thread
Component = if ($attributeMatch.Success) { $attributeMatch.Groups[1].Value } else { '' }
Thread = if ($attributeMatch.Success) { [int]$attributeMatch.Groups[3].Value } else { $null }
Event = $null
Detail = $null
Id = $null
Message = $match.Groups['message'].Value.TrimEnd("`r", "`n")
Message = $message.TrimEnd("`r", "`n")
Log = $logName
Line = $line
}
}
}

# component, then type, then thread, in the order every agent log writes them; context and file
# sit between and after them and are not read
$script:IslCmTraceAttributeRegex = [regex]::new('component="([^"]*)".*?type="(\d)".*?thread="(\d+)"',

@fadwen fadwen Oct 6, 2026

Copy link
Copy Markdown
Owner Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One expression in the agent's attribute order replaces three. If a record lacks any of the three the whole match fails and the entry falls back to the defaults (no component, Information, no thread), as it did when the individual match failed.

[System.Text.RegularExpressions.RegexOptions]::Compiled)
25 changes: 13 additions & 12 deletions Private/ConvertTo-IslCmTraceTime.ps1
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -30,17 +30,18 @@ function ConvertTo-IslCmTraceTime {
[string]$Date
)

$timeMatch = [regex]::Match($Time, '^(\d{1,2}):(\d{2}):(\d{2})(?:\.(\d{1,7}))?')
$dateMatch = [regex]::Match($Date, '^(\d{1,2})-(\d{1,2})-(\d{4})$')
if (-not $timeMatch.Success -or -not $dateMatch.Success) {
throw "Not a CMTrace timestamp: date=$Date time=$Time"
}
$timeParts = $timeMatch.Groups
$dateParts = $dateMatch.Groups
$value = [datetime]::new([int]$dateParts[3].Value, [int]$dateParts[1].Value, [int]$dateParts[2].Value,
[int]$timeParts[1].Value, [int]$timeParts[2].Value, [int]$timeParts[3].Value)
if ($timeParts[4].Success) {
$value = $value.AddTicks([long]$timeParts[4].Value.PadRight(7, '0'))
}
# This runs once per log entry. The bias is cut off at the first + or - after the seconds, and
# one TryParseExact reads the rest: the F specifiers take any number of fraction digits up to
# seven, and none at all
$bias = $Time.IndexOfAny([char[]]@('+', '-'), [Math]::Min(7, $Time.Length))
$plain = if ($bias -ge 0) { $Time.Substring(0, $bias) } else { $Time }
$value = [datetime]::MinValue
$parsed = [datetime]::TryParseExact("$Date $plain", $script:IslCmTraceTimeFormat,
[cultureinfo]::InvariantCulture, [System.Globalization.DateTimeStyles]::None, [ref]$value)
if (-not $parsed) { throw "Not a CMTrace timestamp: date=$Date time=$Time" }
$value
}

# M-d-yyyy and H:mm:ss as the agent writes them: no leading zero on the month, day or hour is
# required, and the fraction is optional
$script:IslCmTraceTimeFormat = 'M-d-yyyy H:mm:ss.FFFFFFF'
Loading
Loading