AuditLog set-based ingest deadlocks (1205) under concurrent writers #124

New Issue

2026-11-10T15:58:38-05:00

dohertj2 commented

2026-11-10 15:58:38 -05:00

Found by the #49 [xc-4] run (docs/plans/2026-11-10-wp4-residual-scope-results.md §5, ResidualBench audit).

Four concurrent callers of AuditLogRepository.InsertManyIfNotExistsAsync, each inserting 256-row packets into a freshly migrated database, hit SQL error 1205 (deadlock victim) within seconds. The deadlock is in the set-based INSERT … SELECT … WHERE NOT EXISTS (EventId) of InsertChunkAsync. A single serial writer, which is the shape AuditLogIngestActor (a cluster singleton) actually runs, inserted 1 M rows with zero deadlocks.

Production can still run concurrent inserts into AuditLog:

the ingest singleton;
the SiteAuditReconciliationActor singleton (also InsertManyIfNotExistsAsync);
the cached-telemetry dual-write;
CentralAuditWriter direct writes.

AuditIngestErrorClassifier already treats 1205 as transient, so a site re-sends its packet and nothing is lost. The cost is a wasted round trip plus a Warning, and a risk of retry storms if both singletons ingest a large backlog at once (e.g. after an outage).

Worth checking:

Whether the ingest and reconciliation singletons deadlock each other at realistic sizes. This is only a lab observation so far.
Whether the insert should retry 1205 locally once before surfacing it, as EF's execution strategy would.
Whether a lock hint (WITH (UPDLOCK, HOLDLOCK) on the probe, or ROWLOCK) removes the cycle.

The deadlock graph was not captured.

Found by the #49 `[xc-4]` run (`docs/plans/2026-11-10-wp4-residual-scope-results.md` §5, `ResidualBench audit`). Four **concurrent** callers of `AuditLogRepository.InsertManyIfNotExistsAsync`, each inserting 256-row packets into a freshly migrated database, hit **SQL error 1205 (deadlock victim)** within seconds. The deadlock is in the set-based `INSERT … SELECT … WHERE NOT EXISTS (EventId)` of `InsertChunkAsync`. A single serial writer, which is the shape `AuditLogIngestActor` (a cluster singleton) actually runs, inserted 1 M rows with **zero** deadlocks. Production can still run concurrent inserts into `AuditLog`: - the ingest singleton; - the `SiteAuditReconciliationActor` singleton (also `InsertManyIfNotExistsAsync`); - the cached-telemetry dual-write; - `CentralAuditWriter` direct writes. `AuditIngestErrorClassifier` already treats 1205 as transient, so a site re-sends its packet and nothing is lost. The cost is a wasted round trip plus a Warning, and a risk of retry storms if both singletons ingest a large backlog at once (e.g. after an outage). Worth checking: 1. Whether the ingest and reconciliation singletons deadlock each other at realistic sizes. This is only a lab observation so far. 2. Whether the insert should retry 1205 locally once before surfacing it, as EF's execution strategy would. 3. Whether a lock hint (`WITH (UPDLOCK, HOLDLOCK)` on the probe, or `ROWLOCK`) removes the cycle. The deadlock graph was not captured.

dohertj2 added the priority:p3 type:review-finding labels 2026-11-10 15:58:54 -05:00

dohertj2 referenced this issue from a commit

2026-11-10 16:46:46 -05:00

test(perf): measure phase-8 WP-4 residual criteria xc-3/4/5/8 (#49)

dohertj2 referenced this issue from a commit

2026-11-10 16:46:46 -05:00

fix: outbox KPI per-status legs, composite event-log indexes, AuditLog ingest FORCESEEK (#122, #123, #124)

dohertj2 referenced this issue

2026-11-10 16:47:01 -05:00

Measure WP-4 residual load criteria (site-event-log retention, audit load vs central, large-template flatten, UI under load) #49

dohertj2 commented

2026-11-10 16:47:02 -05:00

Fixed in 424db155.

Captured deadlock graph. Both processes are INSERTs at READ COMMITTED, holding and waiting on page locks on AuditLog (one holds S on page A and wants S on page B; the other holds IX on B and wants IX on A). The NOT EXISTS (… WHERE x.EventId = v.EventId) probe of a 256-row packet was being answered by scanning the EventId index. A scan keeps its current page's S lock while it requests the next, and the other writer had just written into those pages.

Fix. The probe is FROM dbo.AuditLog x WITH (FORCESEEK): one seek per VALUES row, locking only the key it reads and only while reading it. A seek can still wait on another writer's uncommitted row with the same EventId. That is a genuine duplicate, and the existing duplicate-key fallback already handles it.

Measured with a new ResidualBench audit-contention mode: N concurrent writers of 256-row packets on a throwaway migrated database. One writer replays already-sent packets, as a reconciliation pull overlaps live telemetry.

	writers	rows/s	1205 victims
before	1	1,737	0
before	4	775	76 in 30 s (of 173 packets)
FORCESEEK	1	1,723	0
FORCESEEK	4	5,214	0
FORCESEEK	8	8,607	0

READPAST on top of FORCESEEK added nothing (4,007 rows/s), so it was left out.

Regression test. AuditLogRepositoryTests.InsertManyIfNotExistsAsync_ConcurrentWriters_DoNotDeadlock (real SQL Server fixture) seeds 10 k rows, then runs 4 writers × 15 packets over the same time window. Without the hint it failed 4 out of 4 runs (40–43 of 60 packets lost to 1205); with the hint it passed 3 out of 3. The full AuditLog repository suite passes (129).

On the three questions in the issue: (1) concurrent singletons deadlocking each other: yes, that was this cycle, and it is gone. (2) A local 1205 retry: not added. The cycle is removed rather than retried, and a retry would be wrong inside the cached-telemetry dual-write's ambient transaction, which a deadlock rolls back as a whole. (3) A lock hint: FORCESEEK is the one that removes the cycle.

Fixed in 424db155. **Captured deadlock graph.** Both processes are `INSERT`s at READ COMMITTED, holding and waiting on **page** locks on `AuditLog` (one holds `S` on page A and wants `S` on page B; the other holds `IX` on B and wants `IX` on A). The `NOT EXISTS (… WHERE x.EventId = v.EventId)` probe of a 256-row packet was being answered by *scanning* the EventId index. A scan keeps its current page's S lock while it requests the next, and the other writer had just written into those pages. **Fix.** The probe is `FROM dbo.AuditLog x WITH (FORCESEEK)`: one seek per VALUES row, locking only the key it reads and only while reading it. A seek can still wait on another writer's uncommitted row with the *same* EventId. That is a genuine duplicate, and the existing duplicate-key fallback already handles it. **Measured** with a new `ResidualBench audit-contention` mode: N concurrent writers of 256-row packets on a throwaway migrated database. One writer replays already-sent packets, as a reconciliation pull overlaps live telemetry. | | writers | rows/s | 1205 victims | |---|---|---|---| | before | 1 | 1,737 | 0 | | before | 4 | 775 | 76 in 30 s (of 173 packets) | | FORCESEEK | 1 | 1,723 | 0 | | FORCESEEK | 4 | 5,214 | 0 | | FORCESEEK | 8 | 8,607 | 0 | `READPAST` on top of `FORCESEEK` added nothing (4,007 rows/s), so it was left out. **Regression test.** `AuditLogRepositoryTests.InsertManyIfNotExistsAsync_ConcurrentWriters_DoNotDeadlock` (real SQL Server fixture) seeds 10 k rows, then runs 4 writers × 15 packets over the same time window. Without the hint it failed 4 out of 4 runs (40–43 of 60 packets lost to 1205); with the hint it passed 3 out of 3. The full AuditLog repository suite passes (129). On the three questions in the issue: (1) concurrent singletons deadlocking each other: yes, that was this cycle, and it is gone. (2) A local 1205 retry: not added. The cycle is removed rather than retried, and a retry would be wrong inside the cached-telemetry dual-write's ambient transaction, which a deadlock rolls back as a whole. (3) A lock hint: `FORCESEEK` is the one that removes the cycle.

dohertj2 closed this issue

2026-11-10 16:47:03 -05:00

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: dohertj2/ScadaBridge#124