perf(site-runtime): operation tracking store writes off the script thread (single-writer queue, batch per transaction)

A Flow Debugger live run (execution 1130c01f) spent 108 of a 176 ms site script run between the cached DB write completing and Notify.Send starting: the immediate- completion telemetry awaited two autocommit SQLite transactions on the consolidated LocalDb file (RecordAttemptAsync + RecordTerminalAsync), on the script thread, each a WAL fsync on a Docker volume; the submit row was a third. The audit half of the same forwarder was already a channel write, so the tracking half was the whole cost. OperationTrackingStore is now a single-writer queue: Record*Async enqueue an ordered work item and return; one background pump drains the bounded channel (8192, wait backpressure - tracking never drops) and applies each batch (<=256) in ONE transaction, falling back to per-row apply when a batch fails so a poison row cannot take its neighbours. Preserved invariants: FIFO across enqueue/attempt/terminal; read-your- writes (GetStatusAsync and ReadChangedSinceAsync barrier on every write queued before them, skipped when idle) so Tracking.Status, the telemetry actor's status join and central's PullSiteCalls never see a stale row; timestamps stamped when recorded; PurgeTerminalAsync returns after the purge lands; DisposeAsync drains the queue before closing; sync Dispose keeps its documented in-flight-writes-fail semantics. New public FlushAsync() is the explicit barrier. Accepted: a queued-but-unapplied row is lost on a hard crash (ms window); S&F buffer and audit rows are unaffected. No interface, forwarder or ScriptRuntimeContext change. Tests: write returns while another connection holds the DB write lock and lands once released (fails on the old store: 31 s); reads see 100 ordered attempts + terminal; DisposeAsync drains 200 queued rows; write after dispose throws ObjectDisposed. Existing tests that poke the SQLite file right after a store call now FlushAsync first. Claude-Session: https://claude.ai/code/session_01NcMG6xXdsJbmD2wYAgkK29
2026-09-06 12:25:58 -04:00
parent 7caf56f332
commit d91135f960
6 changed files with 461 additions and 68 deletions
@@ -489,8 +489,8 @@ public class OperationTrackingStoreTests : IDisposable

        // Backdate the (a) row's TerminalAtUtc to 30 days ago via a direct UPDATE
        // — RecordTerminalAsync stamps DateTime.UtcNow which we cannot inject.
-        // The verifier connection shares the same in-memory store thanks to
-        // mode=memory&cache=shared.
+        // Flush first: the writes above are queued, and the verifier goes to the file.
+        await store.FlushAsync();
        using (var connection = OpenVerifierConnection(dataSource))
        using (var cmd = connection.CreateCommand())
        {
@@ -531,6 +531,7 @@ public class OperationTrackingStoreTests : IDisposable
        // can be placed cleanly between rows. (Enqueue stamps DateTime.UtcNow;
        // we cannot inject the clock, so set the timestamps directly.)
        var t0 = new DateTime(2026, 1, 1, 0, 0, 0, DateTimeKind.Utc);
+        await store.FlushAsync(); // writes are queued; the verifier connection needs them applied
        SetUpdatedAt(dataSource, older, t0);
        SetUpdatedAt(dataSource, middle, t0.AddMinutes(10));
        SetUpdatedAt(dataSource, newer, t0.AddMinutes(20));
@@ -572,6 +573,7 @@ public class OperationTrackingStoreTests : IDisposable
            var id = TrackedOperationId.New();
            ids.Add(id);
            await store.RecordEnqueueAsync(id, nameof(AuditKind.ApiCallCached), $"T{i}", null, null, null);
+            await store.FlushAsync();
            SetUpdatedAt(dataSource, id, t0.AddMinutes(i));
        }

@@ -642,6 +644,102 @@ public class OperationTrackingStoreTests : IDisposable
        cmd.ExecuteNonQuery();
    }

+    // ── 2026-09-06: writes off the script thread (single-writer queue) ─────
+    // Design: docs/plans/2026-09-06-tracking-store-async-writes-design.md
+
+    [Fact]
+    public async Task Write_ReturnsWhileAnotherConnectionHoldsTheWriteLock_AndLandsOnceReleased()
+    {
+        // The caller (a script thread, via CachedCallTelemetryForwarder) must not pay for the
+        // SQLite commit. Proof: hold the database's write lock from a second connection so the
+        // commit CANNOT proceed, and require RecordEnqueueAsync to return anyway. LocalDb's
+        // busy_timeout is 5 s, so the pump's commit blocks and then succeeds once we release.
+        var (store, path) = CreateStore(nameof(Write_ReturnsWhileAnotherConnectionHoldsTheWriteLock_AndLandsOnceReleased));
+        await using (store)
+        {
+            using var locker = OpenVerifierConnection(path);
+            using (var lockCmd = locker.CreateCommand())
+            {
+                lockCmd.CommandText = "BEGIN IMMEDIATE;";
+                lockCmd.ExecuteNonQuery();
+            }
+
+            var id = TrackedOperationId.New();
+            var sw = System.Diagnostics.Stopwatch.StartNew();
+            var write = store.RecordEnqueueAsync(id, "DbWriteCached", "RigDb", "Sim01", "OutboundDemo", "node-a");
+            var finished = await Task.WhenAny(write, Task.Delay(TimeSpan.FromSeconds(2)));
+            sw.Stop();
+            Assert.Same(write, finished); // returned although the commit is blocked
+            Assert.True(sw.Elapsed < TimeSpan.FromSeconds(1), $"write took {sw.Elapsed}");
+
+            using (var unlock = locker.CreateCommand())
+            {
+                unlock.CommandText = "COMMIT;";
+                unlock.ExecuteNonQuery();
+            }
+
+            var snapshot = await store.GetStatusAsync(id);
+            Assert.NotNull(snapshot);
+            Assert.Equal("Submitted", snapshot!.Status);
+        }
+    }
+
+    [Fact]
+    public async Task Reads_SeeEveryWriteQueuedBeforeThem_InOrder()
+    {
+        // Read-your-writes + FIFO: Tracking.Status right after a burst of lifecycle writes must
+        // observe the LAST one, never a stale intermediate state.
+        var (store, _) = CreateStore(nameof(Reads_SeeEveryWriteQueuedBeforeThem_InOrder));
+        await using (store)
+        {
+            var id = TrackedOperationId.New();
+            var writes = new List<Task>
+            {
+                store.RecordEnqueueAsync(id, "ApiCallCached", "ERP.GetOrder", null, null, "node-a"),
+            };
+            for (var i = 1; i <= 100; i++)
+                writes.Add(store.RecordAttemptAsync(id, "Retrying", retryCount: i, lastError: $"attempt {i}", httpStatus: 503));
+            writes.Add(store.RecordTerminalAsync(id, "Delivered", null, 200));
+            await Task.WhenAll(writes);
+
+            var snapshot = await store.GetStatusAsync(id);
+            Assert.NotNull(snapshot);
+            Assert.Equal("Delivered", snapshot!.Status);
+            Assert.Equal(100, snapshot.RetryCount);
+            Assert.NotNull(snapshot.TerminalAtUtc);
+
+            var changed = await store.ReadChangedSinceAsync(DateTime.MinValue, batchSize: 10);
+            Assert.Single(changed);
+            Assert.Equal("Delivered", changed[0].Status);
+        }
+    }
+
+    [Fact]
+    public async Task DisposeAsync_DrainsQueuedWrites_BeforeClosingTheConnection()
+    {
+        var (store, path) = CreateStore(nameof(DisposeAsync_DrainsQueuedWrites_BeforeClosingTheConnection));
+        var writes = Enumerable.Range(0, 200)
+            .Select(i => store.RecordEnqueueAsync(TrackedOperationId.New(), "ApiCallCached", $"ERP.Op{i}", null, null, "node-a"))
+            .ToArray();
+        await Task.WhenAll(writes); // queued, not necessarily applied
+
+        await store.DisposeAsync();
+
+        using var verifier = OpenVerifierConnection(path);
+        using var count = verifier.CreateCommand();
+        count.CommandText = "SELECT COUNT(*) FROM OperationTracking;";
+        Assert.Equal(200L, (long)count.ExecuteScalar()!);
+    }
+
+    [Fact]
+    public async Task Write_AfterDispose_ThrowsObjectDisposed()
+    {
+        var (store, _) = CreateStore(nameof(Write_AfterDispose_ThrowsObjectDisposed));
+        await store.DisposeAsync();
+        await Assert.ThrowsAsync<ObjectDisposedException>(() =>
+            store.RecordEnqueueAsync(TrackedOperationId.New(), "ApiCallCached", null, null, null, null));
+    }
+
    // ── SiteRuntime-024: read/write split + sync-safe Dispose ──────────────

    [Fact]
@@ -815,6 +913,7 @@ public class OperationTrackingStoreTests : IDisposable
                sourceInstanceId: "I", sourceScript: "S", sourceNode: "node-a");
        }

+        await store.FlushAsync();
        var boundary = ForceSharedUpdatedAt(dataSource);

        // Page 1: no cursor → the first batchSize rows, ordered by TrackedOperationId.
@@ -855,6 +954,7 @@ public class OperationTrackingStoreTests : IDisposable
                sourceInstanceId: "I", sourceScript: "S", sourceNode: "node-a");
        }

+        await store.FlushAsync();
        var boundary = ForceSharedUpdatedAt(dataSource);

        var page1 = await store.ReadChangedSinceAsync(boundary, batchSize);