fix(agent): IME matcher line budget charges thread CPU cycles, regex timeouts get one starvation-gated retry - the wall-clock budget and the 1s .NET regex timeout both measured guest-scheduler starvation as match cost on CPU-saturated Hyper-V VMs (session b9f1d134: PS-AGENT-OUTPUT timed out on a line it genuinely matches in 5.8us, factor ~170,000, with 2.5s of process-wide log silence and CPU pinned at 100% during the DeviceSetup script burst; six spurious budget breaks the same pass); MatchLine now charges the per-line budget in cycles the poll thread actually executed (QueryThreadCycleTime, probed once, Stopwatch wall-tick fallback preserving the old behaviour exactly), and a RegexMatchTimeoutException whose attempt consumed < 0.5s of match cost (starvation, not spinning) is retried exactly once - counted into the new regexTimeoutRetries (recovered, NOT skipped work, no degraded event) while an attempt at/over the gate is skipped without a second helping of CPU, so regexTimeouts now means "really burned CPU"; the gate is unreachable in the wall-clock fallback by construction (no retry there); retries surfaced through health snapshot, restart-safe persistence, ime_tracker_degraded, ime_pattern_hits and agent_metrics_snapshot (ime_regex_timeout_retries); known limit: hypervisor-level vCPU steal stays invisible to the guest kernel and still charges cycles - strict improvement over wall clock, not perfect steal accounting

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Oliver Kieselbach
2026-08-30 21:49:15 +02:00
parent 5f3ae2d06b
commit 2b6565b3cb
9 changed files with 302 additions and 31 deletions
@@ -3,6 +3,7 @@ using System.Collections.Generic;
using System.IO;
using System.Linq;
using System.Text;
using System.Text.RegularExpressions;
using System.Threading;
using System.Threading.Tasks;
using AutopilotMonitor.Agent.V2.Core.Logging;
@@ -158,6 +159,130 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
Assert.False(health.HasSkippedWork);
}
[Fact]
public async Task Starved_timeout_is_retried_once_and_the_recovered_match_is_not_skipped_work()
{
// Session b9f1d134: a CPU-starved Hyper-V guest tripped the 1 s wall-clock regex
// timeout on a line the pattern genuinely matches in 5.8 µs. A timeout whose attempt
// consumed almost no match cost is starvation — retried once, recovered, no warning.
using var h = new Harness();
var degraded = 0;
h.Tracker.OnTrackerDegraded = (_, __, ___) => degraded++;
h.Tracker.MatchCostReader = () => 0; // attempt cost 0 < gate
var attempts = 0;
h.Tracker.MatchInvoker = (id, regex, input) =>
{
if (id == "T-MARK" && ++attempts == 1) throw new RegexMatchTimeoutException();
return regex.Match(input);
};
h.Append(Entry("marker 1") + "\n");
await h.Pass();
var health = h.Tracker.GetHealthSnapshot();
Assert.Equal(2, attempts);
Assert.Equal(1, health.PatternHits["T-MARK"]); // recovered
Assert.Equal(0, health.RegexTimeouts);
Assert.Equal(1, health.RegexTimeoutRetries);
Assert.False(health.HasSkippedWork);
Assert.Equal(0, degraded);
}
[Fact]
public async Task Timeout_that_burned_real_cpu_is_skipped_without_a_retry()
{
// The gate exists so a genuinely spinning pattern never gets a second helping of
// CPU: an attempt at or over the gate is a real timeout, counted and skipped. The
// wall-clock fallback lands here by construction (a timed-out attempt always
// measures >= the full timeout > gate).
using var h = new Harness();
var degraded = 0;
h.Tracker.OnTrackerDegraded = (_, __, ___) => degraded++;
h.Tracker.LineMatchBudget = long.MaxValue; // isolate the gate from the budget
long cost = 0;
h.Tracker.MatchCostReader = () => cost += h.Tracker.TimeoutRetryGate; // every delta >= gate
var attempts = 0;
h.Tracker.MatchInvoker = (id, regex, input) =>
{
if (id == "T-MARK") { attempts++; throw new RegexMatchTimeoutException(); }
return regex.Match(input);
};
h.Append(Entry("marker 1 loose 1") + "\n");
await h.Pass();
var health = h.Tracker.GetHealthSnapshot();
Assert.Equal(1, attempts); // no retry
Assert.Equal(0, health.PatternHits["T-MARK"]);
Assert.Equal(1, health.PatternHits["T-LOOSE"]); // later patterns still ran
Assert.Equal(1, health.RegexTimeouts);
Assert.Equal(0, health.RegexTimeoutRetries);
Assert.True(health.HasSkippedWork);
Assert.Equal(1, degraded);
}
[Fact]
public async Task Retry_that_times_out_again_is_counted_once_and_not_retried_further()
{
using var h = new Harness();
h.Tracker.MatchCostReader = () => 0; // every attempt looks starved
var attempts = 0;
h.Tracker.MatchInvoker = (id, regex, input) =>
{
if (id == "T-MARK") { attempts++; throw new RegexMatchTimeoutException(); }
return regex.Match(input);
};
h.Append(Entry("marker 1") + "\n");
await h.Pass();
var health = h.Tracker.GetHealthSnapshot();
Assert.Equal(2, attempts); // exactly one retry
Assert.Equal(1, health.RegexTimeouts);
Assert.Equal(1, health.RegexTimeoutRetries);
Assert.True(health.HasSkippedWork);
}
[Fact]
public async Task Budget_break_skips_the_remaining_patterns_and_names_the_first_skipped()
{
using var h = new Harness();
string? firstSkipped = null;
h.Tracker.OnTrackerDegraded = (_, __, pattern) => firstSkipped = pattern;
h.Tracker.LineMatchBudget = 500;
long cost = 0;
h.Tracker.MatchCostReader = () => cost += 1000; // every Match charges 1000 units
h.Append(Entry("marker 1 loose 1") + "\n");
await h.Pass();
var health = h.Tracker.GetHealthSnapshot();
Assert.Equal("T-NEVER", firstSkipped); // pattern order: T-MARK, T-NEVER, T-LOOSE
Assert.Equal(1, health.PatternHits["T-MARK"]); // matched before the budget was spent
Assert.Equal(0, health.PatternHits["T-LOOSE"]); // skipped by the break
Assert.Equal(1, health.BudgetBreaks);
Assert.True(health.HasSkippedWork);
}
[Fact]
public async Task Retry_counter_survives_a_restart()
{
using var h = new Harness();
h.Tracker.MatchCostReader = () => 0;
var attempts = 0;
h.Tracker.MatchInvoker = (id, regex, input) =>
{
if (id == "T-MARK" && ++attempts == 1) throw new RegexMatchTimeoutException();
return regex.Match(input);
};
h.Append(Entry("marker 1") + "\n");
await h.Pass();
h.Tracker.SaveStateForTest();
h.Restart();
Assert.Equal(1, h.Tracker.GetHealthSnapshot().RegexTimeoutRetries);
}
[Fact]
public void Ime_agent_version_is_captured_from_the_pattern_action()
{
@@ -331,6 +331,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
private sealed class PassStats
{
public int RegexTimeouts;
public int RegexTimeoutRetries;
public int BudgetBreaks;
public int OversizedLines;
public string FirstSkippedPatternId;
@@ -342,23 +343,35 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// remaining patterns are skipped for this line (counted, first skipped ID recorded) —
/// matches already handled on this line stand.
/// <para>
/// The budget is the SUM of the time spent inside <c>Regex.Match</c> on this line — the
/// cost the budget exists to bound (hostile input × unanchored custom patterns). It is
/// deliberately not the wall-clock from the first to the last pattern: that window also
/// contains the match handlers (signal ingress, match-log append, state writes) and
/// whatever the scheduler does to this thread in between. Session 946ccbd6 (2026-08-30)
/// recorded two budget breaks on a 1 MB `AppWorkload.log` with no line over 5 KB — the
/// Hyper-V guest had stalled the whole process for 5–10 s mid-line — and each break
/// silently skipped the remaining patterns of a genuine line.
/// The budget is the SUM of the COST spent inside <c>Regex.Match</c> on this line — the
/// resource the budget exists to bound (hostile input × unanchored custom patterns).
/// Cost is thread CPU cycles when <see cref="ThreadCycleTimeAvailable"/>, wall ticks
/// otherwise. Two production sessions forced the cycle move (both Hyper-V, 2026-08-30):
/// 946ccbd6 — a 5–10 s guest stall BETWEEN two patterns broke the then wall-clock-window
/// budget on a genuine line (fixed by charging only Match time); b9f1d134 — a stall
/// INSIDE Match calls (CPU pinned at 100 % during the DeviceSetup script burst) broke
/// the budget six times and tripped the 1 s regex timeout on a line PS-AGENT-OUTPUT
/// genuinely matches in 5.8 µs. Descheduled time accrues no cycles, so only the second
/// failure mode needed the cost change; the timeout itself is wall-clock inside .NET
/// and cannot be moved — hence the gated single retry below.
/// </para>
/// <para>
/// A <see cref="RegexMatchTimeoutException"/> whose attempt consumed less than
/// <see cref="TimeoutRetryGate"/> of cost was starvation, not matching — that attempt
/// is retried exactly once (counted as a retry, not a timeout; a recovered match is
/// handled normally and is NOT skipped work). An attempt at or over the gate burned
/// real CPU: counted as a timeout and skipped, never granted a second helping. In the
/// wall-clock fallback the gate is unreachable (a timed-out attempt always measures
/// ≥ the full timeout), so the fallback keeps the old skip-on-first-timeout behaviour.
/// </para>
/// </summary>
private void MatchLine(string filePath, string line, string messageToMatch, CmTraceLogEntry entry, PassStats stats)
{
long matchTicks = 0;
long matchCost = 0;
for (var i = 0; i < _activePatterns.Count; i++)
{
var pattern = _activePatterns[i];
if (matchTicks > LineMatchBudgetTicks)
if (matchCost > LineMatchBudget)
{
stats.BudgetBreaks++;
_budgetBreaks++;
@@ -366,22 +379,37 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
return;
}
Match match;
var matchStarted = Stopwatch.GetTimestamp();
try
Match match = null;
var retried = false;
while (true)
{
match = pattern.Regex.Match(messageToMatch);
var costBefore = MatchCostReader();
try
{
match = MatchInvoker(pattern.PatternId, pattern.Regex, messageToMatch);
matchCost += MatchCostReader() - costBefore;
break;
}
catch (RegexMatchTimeoutException)
{
var attemptCost = MatchCostReader() - costBefore;
matchCost += attemptCost;
if (!retried && attemptCost < TimeoutRetryGate)
{
retried = true;
stats.RegexTimeoutRetries++;
_regexTimeoutRetries++;
_logger.Debug($"ImeLogTracker: regex timeout for pattern '{pattern.PatternId}' consumed only {attemptCost} match-cost units (< gate {TimeoutRetryGate}) — starved thread, retrying once");
continue;
}
stats.RegexTimeouts++;
_regexTimeouts++;
if (_timeoutLoggedPatternIds.Add(pattern.PatternId))
_logger.Debug($"ImeLogTracker: regex timeout for pattern '{pattern.PatternId}' (message length {messageToMatch.Length}, attempt cost {attemptCost}) — skipped; further timeouts of this pattern are only counted");
break;
}
}
catch (RegexMatchTimeoutException)
{
matchTicks += Stopwatch.GetTimestamp() - matchStarted;
stats.RegexTimeouts++;
_regexTimeouts++;
if (_timeoutLoggedPatternIds.Add(pattern.PatternId))
_logger.Debug($"ImeLogTracker: regex timeout for pattern '{pattern.PatternId}' (message length {messageToMatch.Length}) — skipped; further timeouts of this pattern are only counted");
continue;
}
matchTicks += Stopwatch.GetTimestamp() - matchStarted;
if (match == null) continue;
if (match.Success)
{
@@ -241,12 +241,55 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
// (IME writes an entry in one call) is far smaller.
internal const int HeldTailMaxBytes = 1024 * 1024;
// Aggregate matching budget per line across ALL active patterns. The 1 s per-regex
// timeout bounds one Match call; with ~80 active patterns and tenant-authored custom
// patterns (which are not anchored) a crafted line could still serialize ~80 s. After
// this budget the remaining patterns are skipped for that line and the pass summary
// says so. No genuine IME line comes anywhere near it.
private static readonly long LineMatchBudgetTicks = Stopwatch.Frequency * 2;
// Per-Match wall-clock timeout baked into every compiled Regex. .NET checks it against
// the wall clock internally, so it CANNOT be moved to CPU time — the starvation retry
// below exists precisely because of that.
internal static readonly TimeSpan RegexMatchTimeout = TimeSpan.FromSeconds(1);
// Whether per-thread CPU cycle accounting is available (probed once). When it is, the
// line budget and the timeout-retry gate are charged in cycles the matching thread
// actually executed; when not, both fall back to wall-clock Stopwatch ticks — exactly
// the pre-cycle behaviour, including "no retry ever" (see TimeoutRetryGate).
internal static readonly bool ThreadCycleTimeAvailable = Interop.ThreadNativeMethods.Probe();
// Converts "seconds of hostile CPU" into a cycle budget. Nominal frequency is unknowable
// in advance and precision is irrelevant: genuine lines cost microseconds (session
// b9f1d134: PS-AGENT-OUTPUT on its worst real line = 5.8 µs), the budget bounds seconds.
// A 1 GHz machine gets an effective 6 s budget, a 5 GHz machine 1.2 s — both fine.
private const long AssumedCyclesPerSecond = 3_000_000_000;
// Aggregate matching budget per line across ALL active patterns, charged in match COST
// (thread CPU cycles when available, wall ticks otherwise). The per-regex timeout bounds
// one Match call; with ~80 active patterns and tenant-authored custom patterns (which
// are not anchored) a crafted line could still serialize ~80 s of CPU. After this budget
// the remaining patterns are skipped for that line and the pass summary says so. No
// genuine IME line comes anywhere near it — but a starved thread no longer trips it,
// because descheduled time accrues no cycles (sessions 946ccbd6 / b9f1d134, 2026-08-30).
// Instance field as a test seam; initialised from the probed static default.
internal long LineMatchBudget =
ThreadCycleTimeAvailable ? AssumedCyclesPerSecond * 2 : Stopwatch.Frequency * 2;
// Gate for the ONE retry after a RegexMatchTimeoutException: retry only when the
// timed-out attempt consumed less than ~0.5 s of match cost — then the 1 s wall-clock
// timeout was starvation, and the retry costs what the match really costs (µs). A
// genuinely spinning pattern burns ~1 s of CPU into the attempt, exceeds the gate and
// is skipped without a second helping. In the wall-clock fallback the gate is
// unreachable by construction (a timed-out attempt always measures >= 1 s wall), so no
// retry ever fires there — starvation and spinning are indistinguishable without
// cycle accounting, and retrying a genuine spinner would double the hostile bound.
internal long TimeoutRetryGate =
ThreadCycleTimeAvailable ? AssumedCyclesPerSecond / 2 : Stopwatch.Frequency / 2;
// Monotonic per-thread match-cost counter (cycles or wall ticks; deltas taken around
// each Regex.Match on the poll thread only). Test seam.
internal Func<long> MatchCostReader = ThreadCycleTimeAvailable
? (Func<long>)Interop.ThreadNativeMethods.GetCurrentThreadCycles
: Stopwatch.GetTimestamp;
// Test seam for MatchLine: lets tests throw RegexMatchTimeoutException deterministically
// for a chosen pattern instead of constructing a genuinely catastrophic regex.
internal Func<string, Regex, string, Match> MatchInvoker =
(patternId, regex, input) => regex.Match(input);
// An unterminated tail at EOF (a physical line without '\n', or a multiline entry
// without its ']LOG]!>' close) is normally the writer mid-write. It is held back —
@@ -279,6 +322,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
private long _entriesMatched;
private long _oversizedLines;
private long _regexTimeouts;
private long _regexTimeoutRetries;
private long _budgetBreaks;
private long _heldTailCount;
private int _unanchoredPatterns;
@@ -306,6 +350,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
EntriesMatched = _entriesMatched,
OversizedLines = _oversizedLines,
RegexTimeouts = _regexTimeouts,
RegexTimeoutRetries = _regexTimeoutRetries,
BudgetBreaks = _budgetBreaks,
HeldTails = _heldTailCount,
HealthScriptResultParseFailures = HealthScriptResultParseFailures,
@@ -733,7 +778,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
var regexStr = pattern.Pattern.Replace("{GUID}", GuidPattern);
// Singleline: make '.' match newlines too — required because multiline CMTrace
// entries are reassembled with '\n' chars (e.g. DO TEL JSON in IME >= 1.101)
var regex = new Regex(regexStr, RegexOptions.IgnoreCase | RegexOptions.Compiled | RegexOptions.Singleline, TimeSpan.FromSeconds(1));
var regex = new Regex(regexStr, RegexOptions.IgnoreCase | RegexOptions.Compiled | RegexOptions.Singleline, RegexMatchTimeout);
var compiled = new CompiledPattern
{
@@ -1000,6 +1045,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
_entriesMatched = state.Health.EntriesMatched;
_oversizedLines = state.Health.OversizedLines;
_regexTimeouts = state.Health.RegexTimeouts;
_regexTimeoutRetries = state.Health.RegexTimeoutRetries;
_budgetBreaks = state.Health.BudgetBreaks;
_heldTailCount = state.Health.HeldTails;
HealthScriptResultParseFailures = state.Health.HealthScriptResultParseFailures;
@@ -1068,6 +1114,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
EntriesMatched = _entriesMatched,
OversizedLines = _oversizedLines,
RegexTimeouts = _regexTimeouts,
RegexTimeoutRetries = _regexTimeoutRetries,
BudgetBreaks = _budgetBreaks,
HeldTails = _heldTailCount,
HealthScriptResultParseFailures = HealthScriptResultParseFailures,
@@ -21,6 +21,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
public long EntriesMatched { get; set; }
public long OversizedLines { get; set; }
public long RegexTimeouts { get; set; }
/// <summary>
/// Regex timeouts absorbed by the one gated retry: the timed-out attempt consumed
/// almost no CPU (a starved thread, not a spinning pattern) and the retry recovered
/// the match. Expected nonzero on CPU-saturated VMs; NOT skipped work — only a
/// timeout that survives (or is denied) the retry counts into <see cref="RegexTimeouts"/>.
/// </summary>
public long RegexTimeoutRetries { get; set; }
public long BudgetBreaks { get; set; }
public long HeldTails { get; set; }
public int HealthScriptResultParseFailures { get; set; }
@@ -159,6 +159,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
public long EntriesMatched { get; set; }
public long OversizedLines { get; set; }
public long RegexTimeouts { get; set; }
public long RegexTimeoutRetries { get; set; }
public long BudgetBreaks { get; set; }
public long HeldTails { get; set; }
public int HealthScriptResultParseFailures { get; set; }
@@ -0,0 +1,58 @@
using System;
using System.Runtime.InteropServices;
namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Interop
{
/// <summary>
/// Win32 P/Invoke for per-thread CPU accounting. Used by ImeLogTracker to charge the
/// per-line match budget with cycles the matching thread actually executed instead of
/// wall-clock time: on a CPU-saturated guest the wall clock keeps running while the
/// thread is descheduled, so a wall-based budget measures the scheduler, not the regex
/// (sessions 946ccbd6 / b9f1d134, 2026-08-30).
/// </summary>
internal static class ThreadNativeMethods
{
// Pseudo handle (-2): always refers to the calling thread, never needs closing.
[DllImport("kernel32.dll")]
private static extern IntPtr GetCurrentThread();
// Cycles the thread has executed, accumulated by the kernel at context switches.
// Excludes time the thread spent descheduled by the GUEST scheduler; hypervisor-level
// vCPU preemption is invisible to the guest kernel and still gets charged — the
// measurement is a strict improvement over wall clock, not perfect steal accounting.
[DllImport("kernel32.dll")]
private static extern bool QueryThreadCycleTime(IntPtr threadHandle, out ulong cycleTime);
/// <summary>
/// Cycle count of the calling thread, or 0 if the call fails. A 0 makes the caller's
/// delta accounting charge nothing for the enclosed work — the safe direction (no
/// spurious skips); persistent unavailability is ruled out by <see cref="Probe"/>.
/// </summary>
public static long GetCurrentThreadCycles()
{
try
{
ulong cycles;
return QueryThreadCycleTime(GetCurrentThread(), out cycles) ? unchecked((long)cycles) : 0L;
}
catch (Exception)
{
return 0L;
}
}
/// <summary>One-shot availability check (missing export, denied call).</summary>
public static bool Probe()
{
try
{
ulong cycles;
return QueryThreadCycleTime(GetCurrentThread(), out cycles);
}
catch (Exception)
{
return false;
}
}
}
}
@@ -201,6 +201,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
data["ime_entries_matched"] = health.EntriesMatched;
data["ime_oversized_lines"] = health.OversizedLines;
data["ime_regex_timeouts"] = health.RegexTimeouts;
data["ime_regex_timeout_retries"] = health.RegexTimeoutRetries;
data["ime_line_budget_breaks"] = health.BudgetBreaks;
data["ime_held_tails"] = health.HeldTails;
data["ime_unanchored_patterns"] = health.UnanchoredPatterns;
@@ -322,6 +322,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
["file"] = fileName ?? string.Empty,
["oversizedLines"] = health.OversizedLines,
["regexTimeouts"] = health.RegexTimeouts,
["regexTimeoutRetries"] = health.RegexTimeoutRetries,
["lineBudgetBreaks"] = health.BudgetBreaks,
["heldTails"] = health.HeldTails,
["linesRead"] = health.LinesRead,
@@ -579,6 +579,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
["entriesMatched"] = health.EntriesMatched,
["oversizedLines"] = health.OversizedLines,
["regexTimeouts"] = health.RegexTimeouts,
["regexTimeoutRetries"] = health.RegexTimeoutRetries,
["lineBudgetBreaks"] = health.BudgetBreaks,
["heldTails"] = health.HeldTails,
["unanchoredPatterns"] = health.UnanchoredPatterns,