From 0f6a726f79c21046e9513a84c0db92eb9173125f Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Mon, 9 Nov 2026 19:10:42 -0500 Subject: [PATCH] docs(plans): AuditLog clustered-key benchmark, P4 cadence verdict (ScadaBridge#78) Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV --- ...-11-09-auditlog-clustered-key-benchmark.md | 68 +++++++++++++++++++ 1 file changed, 68 insertions(+) create mode 100644 docs/plans/2026-11-09-auditlog-clustered-key-benchmark.md diff --git a/docs/plans/2026-11-09-auditlog-clustered-key-benchmark.md b/docs/plans/2026-11-09-auditlog-clustered-key-benchmark.md new file mode 100644 index 00000000..4fc7c034 --- /dev/null +++ b/docs/plans/2026-11-09-auditlog-clustered-key-benchmark.md @@ -0,0 +1,68 @@ +# AuditLog clustered key benchmark and P4 / P6 follow-ups (ScadaBridge#78) + +Date: 2026-11-09. Status: benchmark record + recommendation only; no migration written. + +## P3 - flip `dbo.AuditLog` clustered key `(EventId, OccurredAtUtc)` -> `(OccurredAtUtc, EventId)`? + +### Facts from the code +- Clustered PK today: `PK_AuditLog (EventId, OccurredAtUtc)` on `ps_AuditLog_Month(OccurredAtUtc)` (monthly RANGE RIGHT partitions); 12 partition-aligned NC indexes (see `AuditLogEntityTypeConfiguration`, migrations `CollapseAuditLogToCanonical`, `AlignAuditLogEventIdUniqueness`, `ReviewRemediationIndexes`, `AddAuditLogHashChain`). +- `EventId` is `Guid.NewGuid()` (`ScadaBridgeAuditEventFactory`, minted at the emitting site): **fully random**, so the current clustered key inserts at random positions inside the active month partition. Every NC index also carries the clustered key as row locator. +- Idempotency (`InsertIfNotExists`, `InsertChunkAsync`, reconciliation) probes `WHERE EventId = @id` - today the clustered key's leading column. Since `AlignAuditLogEventIdUniqueness` there is no separate EventId index. +- Query shapes that range-scan or fetch rows: Audit Log page (`QueryAsync`: `ORDER BY OccurredAtUtc DESC, EventId DESC`, keyset cursor on the same pair, filters on channel/kind/status/site/node/target/actor/execution/correlation + time range), KPI snapshot (`GetKpiSnapshotAsync`, covered by `IX_AuditLog_OccurredAtUtc INCLUDE (Status)`), execution tree/trace (`IX_AuditLog_Execution` + window), hash-chain job (`AuditLogHashChain`: `WHERE ChainSeq IS NULL AND month ORDER BY OccurredAtUtc, EventId`, then UPDATE joined on `(EventId, OccurredAtUtc)`, verification `ORDER BY ChainSeq`), per-channel purge (`DELETE TOP (n) WHERE Category=@c AND OccurredAtUtc<@t`), month archive read, partition-switch purge (metadata only, unaffected). + +### Method +Throwaway SQL Server 2022 (RTM-CU22, Developer, amd64 image under emulation on an Apple-silicon Mac, 6 GB cap, SIMPLE recovery) container, removed afterwards. Table recreated with the production DDL: partition function/scheme, 10 canonical columns, the persisted computed columns, ChainSeq/RowHash, all 12 NC indexes (+ variant-specific). 3,000,000 rows, ~1.9 KB/row (JSON `DetailsJson` ~480 chars), spread over 2026-07-01..2026-11-01, loaded in 3000 chronological batches of 1000 (each row 0-120 s older than its batch, imitating site telemetry delay), random `NEWID()` EventIds, using the production idempotent pattern `INSERT ... WHERE NOT EXISTS (EventId)`. Variants: +- **A** current: clustered `(EventId, OccurredAtUtc)`. +- **B** clustered `(OccurredAtUtc, EventId)`, no EventId index (plain insert, no probe) - shows the pure clustered-key effect. +- **B2** clustered `(OccurredAtUtc, EventId)` + aligned `UNIQUE (EventId, OccurredAtUtc)` NC index - the only variant that keeps cheap idempotency probes and a real EventId uniqueness guarantee. +Queries measured cold (DROPCLEANBUFFERS) and warm with `SET STATISTICS IO, TIME`. Absolute times are inflated by emulation; compare ratios and logical reads. Single run each, no repetition - treat small differences as noise. + +### Insert, size, fragmentation (3M rows) +| Variant | Insert rows/s | Page splits (counter delta) | Clustered pages / MB | Clustered fragmentation | Clustered page fill | +|---|---|---|---|---|---| +| A (current) | 4,022 | 1,122,830 | 735,066 / 5,743 | 99.2% | 64.0% | +| B (no EventId index) | 7,631 | 816,961 | 500,001 / 3,906 | 0.6% | 94.2% | +| B2 (B + unique EventId NC) | 4,065 | 1,141,726 | 735,769 / 5,748 (this is the EventId NC index; clustered was compact) | 99.1% (EventId index) | 63.9% | + +(For B2 the first row of `sys.dm_db_index_physical_stats` sorted by size was the new unique EventId index; the clustered index itself behaved like B.) The NC indexes keyed on site/target/channel etc. fragment similarly in every variant because their leading columns are not time-ordered; B's total page-split count is lower but still large for that reason. + +### Query shapes (logical reads, warm elapsed ms; cold in brackets) +| Shape | A | B | B2 | +|---|---|---|---| +| Q1 Audit Log page 1, newest 50, no filter | 739,300 reads / 2,313 ms [3,855] | 54 / 14 [22] | 51 / 15 [25] | +| Q2 channel IN (..) + 1 day, top 50 | 55,217 / 80 [171] | 58 / 12 [12] | 70 / 16 [18] | +| Q3 site + 1 week, top 100 | 199,502 / 732 [793] | 212 / 14 [15] | 287 / 20 [21] | +| Q4 deep keyset page (cursor in Sept) | 739,300 / 2,750 [1,862] | 70 / 13 [14] | 72 / 18 [20] | +| Q5 KPI last hour (covered) | 7 / 0 | 7 / 0 | 8 / 0 | +| Q6 actor filter, top 50 | 281,077 / 329 [548] | 432 / 1 [13] | 642 / 6 [21] | +| Q9 idempotency probe, 1000 new ids | 24,988 / 159 | 15,444 / 62 (scans a narrow NC index - no EventId index) | 16,204 / 101 | +| Q10 idempotency probe, 1000 existing ids | 24,988 / 85 | 15,444 / 47 | 16,204 / 85 | +| Q11 hash-chain select 5000 unchained | 24,574 / 313 | 1,195 / 290 | 1,678 / 306 | +| Q12 hash-chain stamp 5000 rows | 66,468 / 125 | 66,460 / 107 | 66,466 / 109 | +| Q13 month ordered read (window row_number) | 6,515 / 71 | 3,982 / 56 | 4,108 / 67 | +| Q14 chain verify read, 50k by ChainSeq | 196,306 / 1,213 [1,010] | 136,131 / 153 [688] | 200,724 / 185 [964] | +| Q15 per-channel purge batch 5000 (rolled back) | 195,129 / 458 [654] | 195,140 / 361 [1,592] | 210,211 / 383 [540] | +Q7/Q8 (execution/correlation lookups) returned 0 rows in this synthetic data (id not found) and are not reported; they are NC seeks whose key-lookup locality would favour B slightly. + +Important side finding: in variant A the unfiltered/time-range Audit Log queries (Q1, Q4) read the **entire table** (739k pages at 3M rows) because the ORDER BY `(OccurredAtUtc DESC, EventId DESC)` cannot be satisfied by `IX_AuditLog_OccurredAtUtc` (its implicit trailing key is `EventId ASC`) over a partitioned table. This is a latent performance bug that grows linearly with table size, independent of the flip. A follow-up test adding `IX_alt (OccurredAtUtc DESC, EventId DESC) INCLUDE (Status)` to variant A did NOT fix Q1/Q4 (still 739k reads; forced with a hint it was worse at 12.6M reads), though it cut Q3 from 199k to 4k reads. So an index tweak is not a cheap substitute; the clustered-key flip is what makes the partitioned ordered TOP-N work. + +### Findings +1. The flip is a large, real win for read paths, orders of magnitude on the Audit Log page (the default view) and on every time-range query, plus ~13x fewer reads for the hash-chain job's selection, and sequential month reads. +2. The flip alone also roughly halves insert cost and removes clustered fragmentation (0.6% vs 99.2%, fill 94% vs 64%, 32% smaller table) **because the clustered insert becomes append-only**. +3. But without an EventId index, idempotent ingest (`WHERE NOT EXISTS (EventId)`) degrades to scanning a narrow NC index (B) - the cost grows with table size, and the table loses its uniqueness guarantee. Restoring it with a unique aligned `(EventId, OccurredAtUtc)` index (B2) re-introduces a random-GUID B-tree: insert throughput and fragmentation then match A exactly. So with B2 the flip does **not** help ingest, and the page-split bill moves from the clustered index to the EventId index. +4. Chain stamp (Q12) and purge (Q15) are unchanged within noise; the chain verify read is better in B, equal in B2. + +### Recommendation +**Flip: yes, as B2 (clustered `(OccurredAtUtc, EventId)` + aligned unique NC `(EventId, OccurredAtUtc)`), but schedule it deliberately - it is a priority-appropriate (P3) performance fix, not an urgent one, and the read win (default Audit Log page doing a full-table scan) justifies it as table size grows.** B alone is not recommended (no cheap idempotency probe, no uniqueness guard). Ingest stays at today's cost under B2 (no regression), reads improve by 2-4 orders of magnitude. An optional later step: probe idempotency by the NC index only for rows that might be duplicates (e.g. reconciliation), and drop the probe on the hot telemetry path in favour of catching 2627, which would recover most of B's insert win - not benchmarked here. + +### Migration cost, risk and compatibility (not implemented) +- Rebuild is an offline-ish data move of the whole table (`DROP/CREATE` clustered index, or the `CollapseAuditLogToCanonical`-style new-table-and-copy pattern on the preserved partition scheme). Every one of the 12 NC indexes is rebuilt too (locator changes). On a large table that is hours of I/O and log, and a write outage for the audit path unless `ONLINE = ON` (Enterprise/Developer only; the deployment does not guarantee it - see `AlignAuditLogEventIdUniqueness`). Prefer a maintenance window or per-partition copy while draining ingest (site buffers retain unforwarded rows, so a window is tolerable). +- The hash chain, tombstones, partition-switch purge staging table (`SwitchOutPartitionAsync` hard-codes a byte-identical column list and must declare the same clustered key; a staging-table key mismatch fails SWITCH), the append-only role grants (`DENY UPDATE/DELETE`, `GRANT UPDATE (ChainSeq, RowHash)`), and `AuditLogPartitionArchive` must be re-verified; grants on the table survive an index-only rebuild but not a drop/rename table swap (re-grant as CollapseAuditLogToCanonical did). +- Code: the repository queries need no change (all predicates are on columns, not the key); the EF model declares `HasKey(EventId, OccurredAtUtc)` - EF does not manage the physical clustering (raw SQL), so only the model comment/index declaration should be adjusted. The hash-chain UPDATE join on `(EventId, OccurredAtUtc)` seeks via the unique NC index. +- Mixed-version / rollback: old binaries only issue SQL by column name, so a flipped table works with both old and new binaries, and the flip can be applied before or after an app upgrade; the new-table swap must run with all central nodes stopped or ingest paused. Rollback is the inverse rebuild (same cost) - the migration is reversible in principle, unlike `CollapseAuditLogToCanonical`. Take a backup first. QA/prod must not be touched without the usual deployment gate. + +## P4 - per-node KPI sampling cadence +Verified in code: `KpiHistoryOptions.SampleInterval` (default 60 s, `KpiHistoryRecorderActor` timer at lines ~218-223) is the single cadence; all `IKpiSampleSource`s (including the per-site/per-node scoped series of the Notification Outbox and Site Call Audit sources) are enumerated once per pass and stamped with one shared tick time, with `SourceTimeout` (10 s) bounding each source. No per-node or per-source cadence exists and no requirement document asks for one (Component-KpiHistory.md, Component-HealthMonitoring.md). Nothing is actually open beyond an optional design preference ("should per-node series sample on a different interval?") - recommend closing the P4 item as not-a-defect unless someone supplies a use case. The stale "tracked follow-up" text in Component-ConfigurationDatabase.md has been replaced. + +## P6 - stale spec line +Component-ConfigurationDatabase.md claimed central still sent a bare `sinceUtc` on AuditLog reconciliation pulls. In fact `SiteAuditReconciliationActor` keeps a `(Since, AfterId)` cursor per site and `GrpcPullAuditEventsClient` sends `AfterId`; the site's `ReadPendingSinceAsync` serves strictly-after rows when it is set. The spec line is corrected (same commit as this record).