Joseph Doherty
240 lines
11 KiB
C#
240 lines
11 KiB
C#
using System.Diagnostics;
|
||
using System.Text;
|
||
using Microsoft.Extensions.Logging.Abstractions;
|
||
using Microsoft.Extensions.Options;
|
||
using ZB.MOM.WW.Audit;
|
||
using ZB.MOM.WW.ScadaBridge.AuditLog.Configuration;
|
||
using ZB.MOM.WW.ScadaBridge.AuditLog.Redaction;
|
||
using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit;
|
||
using ZB.MOM.WW.ScadaBridge.Commons.Types.Enums;
|
||
|
||
namespace ZB.MOM.WW.ScadaBridge.PerformanceTests.AuditLog;
|
||
|
||
/// <summary>
|
||
/// Bundle D (M5-T9) / C7 (Task 2.5) hot-path latency budget for
|
||
/// <see cref="ScadaBridgeAuditRedactor"/>. The redactor sits between event
|
||
/// construction and persistence on every audit row — site SQLite hot-path and
|
||
/// central direct-write both — so it MUST stay out of the way of script-thread
|
||
/// latency.
|
||
/// </summary>
|
||
/// <remarks>
|
||
/// <para>
|
||
/// Methodology: warm-up + N iterations, time each
|
||
/// <see cref="ScadaBridgeAuditRedactor.Apply"/> with
|
||
/// <see cref="Stopwatch"/>, sort, take p95, assert under threshold. Matches
|
||
/// the simple-loop style of the existing <c>StaggeredStartupTests</c> /
|
||
/// <c>HealthAggregationTests</c> in this project (no BenchmarkDotNet).
|
||
/// </para>
|
||
/// <para>
|
||
/// <b>C7 re-baseline rationale.</b> The canonical <see cref="ScadaBridgeAuditRedactor"/>
|
||
/// works on a single <c>DetailsJson</c> bag (one JSON parse + one re-serialize per
|
||
/// call) whereas the former typed-field approach touched many individual
|
||
/// fields. Empirical calibration measurements on Apple M-series (2026-06-02, Release build;
|
||
/// the CI test itself runs MeasureIterations=2 000 after WarmupIterations=200):
|
||
/// <list type="bullet">
|
||
/// <item>4 KB body (2 body-regex matches + truncation): p50 ≈ 13 µs, p95 ≈ 14 µs.</item>
|
||
/// <item>Small DetailsJson, no redactors (JSON parse + rewrite only): p50 ≈ 1.5 µs, p95 ≈ 2 µs.</item>
|
||
/// <item>True no-op (null DetailsJson, Target within cap — fast path): p50 ≈ 0 µs, p95 ≈ 0 µs.</item>
|
||
/// </list>
|
||
/// Thresholds are set conservatively to absorb a 15× CI-slowdown factor (shared,
|
||
/// contested runners can be significantly slower than a dev laptop). The env-var
|
||
/// override lets a still-slower runner pass without requiring a code change, while a
|
||
/// true 50× regression still exceeds even the fallback ceiling.
|
||
/// </para>
|
||
/// </remarks>
|
||
public class HotPathLatencyTests
|
||
{
|
||
private const int WarmupIterations = 200;
|
||
private const int MeasureIterations = 2_000;
|
||
|
||
// C3/C7 (Task 2.5): the hot-path redactor is the canonical
|
||
// ScadaBridgeAuditRedactor (IAuditRedactor) operating on the canonical record.
|
||
private static ScadaBridgeAuditRedactor Filter(AuditLogOptions opts) => new(
|
||
new StaticMonitor(opts),
|
||
NullLogger<ScadaBridgeAuditRedactor>.Instance);
|
||
|
||
private static AuditEvent NewEvent(string request) =>
|
||
ScadaBridgeAuditEventFactory.Create(
|
||
channel: AuditChannel.ApiOutbound,
|
||
kind: AuditKind.ApiCall,
|
||
status: AuditStatus.Delivered,
|
||
target: "esg.target",
|
||
requestSummary: request);
|
||
|
||
/// <summary>
|
||
/// Run <paramref name="fn"/> N times, returning the p95 in microseconds.
|
||
/// Single-threaded; <see cref="Stopwatch.GetTimestamp"/> for high-res timing.
|
||
/// </summary>
|
||
private static double MeasureP95Microseconds(int iterations, Action fn)
|
||
{
|
||
var samples = new double[iterations];
|
||
var ticksToMicroseconds = 1_000_000d / Stopwatch.Frequency;
|
||
for (var i = 0; i < iterations; i++)
|
||
{
|
||
var start = Stopwatch.GetTimestamp();
|
||
fn();
|
||
var end = Stopwatch.GetTimestamp();
|
||
samples[i] = (end - start) * ticksToMicroseconds;
|
||
}
|
||
Array.Sort(samples);
|
||
var p95Index = (int)Math.Ceiling(iterations * 0.95) - 1;
|
||
return samples[p95Index];
|
||
}
|
||
|
||
/// <summary>
|
||
/// C7 re-baselined slow-path budget: 4 KiB <c>DetailsJson</c> with two global
|
||
/// body-regex patterns and truncation. The canonical redactor deserializes
|
||
/// DetailsJson, runs header → body-regex → truncation, then re-serializes.
|
||
/// </summary>
|
||
/// <remarks>
|
||
/// Empirical p95 ≈ 14 µs on an Apple M-series (Release build, 2026-06-02).
|
||
/// Budget set to 200 µs (~15× headroom) so a contested shared CI runner does not
|
||
/// produce a flaky red. Override via <c>SCADABRIDGE_AUDIT_FILTER_4KB_P95_US</c>
|
||
/// when running on a known-slow machine without a code change.
|
||
/// </remarks>
|
||
[Trait("Category", "Performance")]
|
||
[Fact]
|
||
public void Filter_Apply_4KB_DetailsJson_DefaultRedactors_P95_LessThan_200_Microseconds()
|
||
{
|
||
// 4 KiB request body inside DetailsJson, laced with a 16-digit token
|
||
// + a `password` field so the body-regex stage matches twice and the
|
||
// truncation stage fires (DetailsJson serialised form > DefaultCapBytes).
|
||
var opts = new AuditLogOptions
|
||
{
|
||
// Keep the cap modest so the truncation path actually fires.
|
||
DefaultCapBytes = 4096,
|
||
GlobalBodyRedactors = new List<string>
|
||
{
|
||
"\"password\":\\s*\"[^\"]*\"",
|
||
"\\d{16}",
|
||
},
|
||
};
|
||
var pad = new string('x', 4 * 1024);
|
||
var body = "{\"user\":\"alice\",\"password\":\"hunter2\",\"card\":\"4111111111111111\",\"pad\":\"" + pad + "\"}";
|
||
// Sanity: the request body we embed must be > 4 KiB so the truncate stage runs.
|
||
Assert.True(Encoding.UTF8.GetByteCount(body) > 4096);
|
||
|
||
var filter = Filter(opts);
|
||
// NewEvent serialises requestSummary into DetailsJson via AuditDetailsCodec —
|
||
// so the canonical JSON parse+rewrite cost IS measured, not elided.
|
||
var evt = NewEvent(body);
|
||
|
||
// Warm-up — JIT, regex compile, dictionary populate.
|
||
for (var i = 0; i < WarmupIterations; i++) _ = filter.Apply(evt);
|
||
|
||
var p95Us = MeasureP95Microseconds(MeasureIterations, () => _ = filter.Apply(evt));
|
||
|
||
// C7 re-baseline: empirical p95 ≈ 14 µs; budget 200 µs (≈ 15× headroom for CI).
|
||
// Old budget was 50 µs (pre-C3 typed-field path, no JSON parse).
|
||
// Override: SCADABRIDGE_AUDIT_FILTER_4KB_P95_US (µs, positive double).
|
||
var threshold = GetThresholdMicroseconds("SCADABRIDGE_AUDIT_FILTER_4KB_P95_US", 200d);
|
||
Assert.True(p95Us < threshold,
|
||
$"4KB DetailsJson slow-path p95 = {p95Us:F1} µs; threshold = {threshold:F1} µs " +
|
||
$"(empirical baseline ≈ 14 µs; budget allows 15× CI headroom)");
|
||
}
|
||
|
||
/// <summary>
|
||
/// C7 re-baselined small-payload budget: small <c>DetailsJson</c> within the
|
||
/// default cap, no redactors configured. The redactor still deserializes and
|
||
/// re-serializes DetailsJson (target IS within cap so the check passes, but
|
||
/// DetailsJson is non-empty so the slow path runs).
|
||
/// </summary>
|
||
/// <remarks>
|
||
/// Empirical p95 ≈ 2 µs on an Apple M-series (Release build, 2026-06-02).
|
||
/// Budget set to 30 µs (~15× headroom). Override via
|
||
/// <c>SCADABRIDGE_AUDIT_FILTER_RAW_P95_US</c>.
|
||
/// </remarks>
|
||
[Trait("Category", "Performance")]
|
||
[Fact]
|
||
public void Filter_Apply_SmallDetailsJson_NoRedactors_P95_LessThan_30_Microseconds()
|
||
{
|
||
// No redactors configured — body-regex list is empty, SQL-param redactor is
|
||
// gated on AuditChannel.DbOutbound (we're ApiOutbound), header redactor
|
||
// short-circuits on non-object DetailsJson fields. Still goes through the
|
||
// slow path because DetailsJson is non-empty (requestSummary was serialized
|
||
// into it by NewEvent). Measures JSON parse + re-serialize baseline.
|
||
var opts = new AuditLogOptions();
|
||
var filter = Filter(opts);
|
||
|
||
// Small payload that fits well under the 8 KiB default cap.
|
||
var evt = NewEvent("hello world");
|
||
|
||
for (var i = 0; i < WarmupIterations; i++) _ = filter.Apply(evt);
|
||
|
||
var p95Us = MeasureP95Microseconds(MeasureIterations, () => _ = filter.Apply(evt));
|
||
|
||
// C7 re-baseline: empirical p95 ≈ 2 µs; budget 30 µs (≈ 15× headroom for CI).
|
||
// Old budget was 10 µs (pre-C3 typed-field path, no JSON parse).
|
||
// Override: SCADABRIDGE_AUDIT_FILTER_RAW_P95_US (µs, positive double).
|
||
var threshold = GetThresholdMicroseconds("SCADABRIDGE_AUDIT_FILTER_RAW_P95_US", 30d);
|
||
Assert.True(p95Us < threshold,
|
||
$"Small-DetailsJson no-redactors p95 = {p95Us:F1} µs; threshold = {threshold:F1} µs " +
|
||
$"(empirical baseline ≈ 2 µs; budget allows 15× CI headroom)");
|
||
}
|
||
|
||
/// <summary>
|
||
/// Fast-path budget: null/empty <c>DetailsJson</c> AND Target within cap — the
|
||
/// redactor returns the input instance immediately without any JSON work.
|
||
/// </summary>
|
||
/// <remarks>
|
||
/// Empirical p95 ≈ 0.05 µs (effectively free) on an Apple M-series (Release
|
||
/// build, 2026-06-02). Budget set to 5 µs — large headroom on an essentially
|
||
/// zero-cost path. Override via <c>SCADABRIDGE_AUDIT_FILTER_NOOP_P95_US</c>.
|
||
/// </remarks>
|
||
[Trait("Category", "Performance")]
|
||
[Fact]
|
||
public void Filter_Apply_NoDetailsJson_FastPath_P95_LessThan_5_Microseconds()
|
||
{
|
||
// Construct a minimal canonical event with no DetailsJson and a null Target
|
||
// so BOTH fast-path conditions are met (detailsEmpty && targetWithinCap).
|
||
// Apply() must return the same instance without deserializing anything.
|
||
var opts = new AuditLogOptions();
|
||
var filter = Filter(opts);
|
||
|
||
var evt = new AuditEvent
|
||
{
|
||
EventId = Guid.NewGuid(),
|
||
OccurredAtUtc = DateTimeOffset.UtcNow,
|
||
Actor = string.Empty,
|
||
Action = "ApiOutbound.ApiCall",
|
||
Category = "ApiOutbound",
|
||
Outcome = AuditOutcome.Success,
|
||
// DetailsJson intentionally null — exercises the true fast path.
|
||
};
|
||
|
||
for (var i = 0; i < WarmupIterations; i++) _ = filter.Apply(evt);
|
||
|
||
var p95Us = MeasureP95Microseconds(MeasureIterations, () => _ = filter.Apply(evt));
|
||
|
||
// Verify same-instance return (fast path must return the input unchanged).
|
||
var result = filter.Apply(evt);
|
||
Assert.Same(evt, result);
|
||
|
||
// C7 baseline: empirical p95 ≈ 0 µs (branch + two null checks); budget 5 µs.
|
||
// Override: SCADABRIDGE_AUDIT_FILTER_NOOP_P95_US (µs, positive double).
|
||
var threshold = GetThresholdMicroseconds("SCADABRIDGE_AUDIT_FILTER_NOOP_P95_US", 5d);
|
||
Assert.True(p95Us < threshold,
|
||
$"No-op fast-path p95 = {p95Us:F1} µs; threshold = {threshold:F1} µs " +
|
||
$"(empirical baseline ≈ 0 µs; fast path returns input unchanged)");
|
||
}
|
||
|
||
private static double GetThresholdMicroseconds(string envVar, double defaultUs)
|
||
{
|
||
var raw = Environment.GetEnvironmentVariable(envVar);
|
||
if (raw != null && double.TryParse(raw, out var parsed) && parsed > 0)
|
||
{
|
||
return parsed;
|
||
}
|
||
return defaultUs;
|
||
}
|
||
|
||
private sealed class StaticMonitor : IOptionsMonitor<AuditLogOptions>
|
||
{
|
||
private readonly AuditLogOptions _value;
|
||
public StaticMonitor(AuditLogOptions value) => _value = value;
|
||
public AuditLogOptions CurrentValue => _value;
|
||
public AuditLogOptions Get(string? name) => _value;
|
||
public IDisposable? OnChange(Action<AuditLogOptions, string?> listener) => null;
|
||
}
|
||
}
|