# Cached-call telemetry off the script thread (tracking store queue + audit enqueue-and-observe)

**Date:** 2026-09-06 · **Status:** implemented and measured the same day (branch `feat/tracking-store-async-writes`)

## Problem

A Flow Debugger live run of `FlowOutboundDemo` (execution `1130c01f-…`) spent 194 ms end to end, of
which the site script run was 176 ms. Reading the audit rows against the code path:

| Segment | Time | What it is |
|---|---|---|
| `ExternalSystem.Call` RigRest.Echo | 4 ms | the REST round trip |
| `Database.CachedWrite` submit → write completed | 61 ms | one tracking-store commit (`RecordEnqueueAsync`) + the MS SQL write |
| write completed → `Notify.Send` starts | **108 ms** | no script statement: the immediate-completion telemetry — two more tracking-store commits (`RecordAttemptAsync`, `RecordTerminalAsync`) |
| `Notify.Send` | ~2 ms | S&F enqueue |

`OperationTrackingStore` executed every `Record*Async` as its own autocommit SQLite transaction on the
consolidated LocalDb file, **awaited inline on the script thread** through
`CachedCallTelemetryForwarder.ForwardAsync`. Each commit is a WAL append + fsync
(`synchronous=NORMAL`, Docker volume). The initial reading — which turned out to be wrong, see the
correction below — was that the audit half of the same forwarder was already cheap because
`SqliteAuditWriter.WriteAsync` enqueues with `Channel.TryWrite`, so the tracking commits were the whole
cost. The API cached-call path (`ExternalSystem.CachedCall`) takes the same three-packet path.

## Decision

Make `OperationTrackingStore` a **single-writer queue**: `Record*Async` enqueue an ordered work item
and return once it is queued; one background pump drains the queue and applies each drained batch in
**one transaction** (one fsync per batch instead of per row). Nothing above the store changes —
`IOperationTrackingStore`, the forwarder, `ScriptRuntimeContext` and the S&F lifecycle bridge are
untouched, and their existing `await`s now cost a channel write.

### Invariants kept

- **FIFO per store.** One bounded channel, one reader, so enqueue → attempt → terminal apply in the
  order they were recorded. The idempotent/first-write-wins SQL is unchanged.
- **Read-your-writes.** `Tracking.Status(id)` (script), the telemetry actor's status join and central's
  `PullSiteCalls` reconciliation all go through `GetStatusAsync`/`ReadChangedSinceAsync`, which now
  **wait for every write queued before the call to be applied** (a barrier through the same queue,
  skipped when nothing is pending). A script that calls `CachedWrite` and then `Tracking.Status` in
  the next statement sees the row exactly as before.
- **Timestamps.** `CreatedAtUtc`/`UpdatedAtUtc`/`TerminalAtUtc` are stamped when the call is
  *recorded*, not when the batch is applied.
- **`PurgeTerminalAsync` returns after the purge is applied** (it rides the queue with a completion).
- **Shutdown drains.** `DisposeAsync` completes the queue and awaits the pump, so queued writes land
  before the connection closes. The synchronous `Dispose()` keeps its documented "in-flight writes
  fail" semantics and must not be used where a drain matters (host shutdown uses the async path).
- **Best-effort failure handling, per row.** A batch that fails is rolled back and re-applied one
  row at a time so a single poison row cannot take the others with it; each failed row logs a
  warning, as the forwarder already did.

### Costs accepted

- **Crash window.** A row queued but not yet applied is lost on a hard crash (SIGKILL, power loss);
  the tracking row then stays at its previous state — e.g. `Submitted` for a call that actually
  delivered — until central's mirror is reconciled from the audit rows, or forever if it was the only
  record. The window is the pump's cadence (sub-millisecond to a few milliseconds under load), and
  the S&F buffer and audit rows, which are the delivery and evidence records, are unaffected. This is
  the same trade the site audit writer made (`FlushIntervalMs`, `synchronous=NORMAL`).
- **Bounded backpressure.** The queue holds `MaxQueuedWrites` (8 192) items; beyond that
  `Record*Async` waits rather than drops — tracking is the status source of truth, so dropping is
  not acceptable. At the volumes this table sees (a handful of rows per cached call) the bound is
  never reached; if it is, the SQLite file is the bottleneck and the wait is the honest signal.
- **A barrier read pays one pump round trip** when writes are pending. It is queued behind at most
  one batch, so worst case it waits for one transaction (~one fsync) — the same cost a read used to
  pay contending for the old write gate.

### Rejected

- *Fire-and-forget from the forwarder* (`_ = _trackingStore.Record…`): loses ordering across the
  three lifecycle rows and read-your-writes, and moves the failure handling to an unobserved task.
- *Batching in the forwarder*: the forwarder is per-packet; only the store sees consecutive rows from
  different runs, which is where batching pays.
- *A bigger LocalDb `synchronous` relaxation*: `OFF` would remove the fsync but risk corruption on
  power loss for every replicated table, not just this one.

## What the measurement actually showed (correction)

The tracking-store queue alone moved **nothing**: five runs on that image still sat at 108 ms for the
DB-done → `Notify.Send` gap and ~176 ms for the script run. The commits were cheap; the wait was the
**audit half** of the same forwarder. `SqliteAuditWriter.WriteAsync` enqueues synchronously but
returns the *batch's completion task*, and the writer loop deliberately coalesces for
`FlushIntervalMs` (50 ms default) before it commits — so every awaited audit row costs ~50 ms + fsync,
and a cached call awaits three of them (submit, attempted, resolve) on the script thread: ~160 ms.
Every other script-path audit emission (`AuditingDbCommand`, `ScriptRunLauncher`, the trace rows)
already fired-and-observed; only `CachedCallTelemetryForwarder.TryEmitAuditAsync` awaited.

Second change, same branch: the forwarder now enqueues the audit row and observes the completion on
a fault-logging continuation (the `FallbackAuditWriter` ring-buffer fallback still runs inside that
task). Nothing joins the audit and tracking stores by commit order; each keeps per-store FIFO.

| Segment (5-run median, rig) | before | tracking queue only | + audit enqueue-and-observe |
|---|---|---|---|
| inbound request total | 194 ms | 186 ms | **25 ms** |
| site script run | 176 ms | 173 ms | **17 ms** |
| `Database.CachedWrite` submit → done | 61 ms | 58 ms | **11 ms** |
| DB done → `Notify.Send` | 108 ms | 108 ms | **0.1 ms** |

The tracking-store queue is kept: it removes three fsyncs per cached call from the script path and
batches them, and `FlushIntervalMs` no longer bounds a script's latency — a cached call now costs
its real I/O (the REST or SQL round trip) plus microseconds of bookkeeping.

## Verification

- Store tests: a write returns while another connection holds the database write lock and lands
  once it is released; reads observe every earlier write in order; `DisposeAsync` drains the queue.
- Forwarder tests: `ForwardAsync` returns while the audit commit is still pending; a late commit
  fault is swallowed and logged.
- Rig: `FlowOutboundDemo` five times per image through `flow-debug run-method`; table above.