Umbrella Request Latency

Umbrella: Request latency on POST /api/execute

Issue: noetl/ai-meta#319 Opened: 2026-09-02 · Status: in progress

The owner's target for NoETL's internal system transactions is microseconds. Measured latency was seconds. This umbrella is the decomposition of that gap into layers that can be fixed independently, and the record of which ones have been.

The decomposition

layer	cost	verdict
P1 — raw EHDB append	~4 ms, stable across every shape	FlushPolicy::EveryAppend takes sync_data() per record. A durability posture, not an inefficiency. Parked behind ehdb#322.
P2 — Postgres round-trips	~45–60 ms of a ~150 ms request	The same catalog row was read four times. Fixed, server#394.
P3 — command publish retry	0	⚠ Diagnosed wrongly. See below.
P0 (found later) — event-log mirror	1.68 s mean, on the request path	The actual tail. Fixed, server#395.
delivery hop	0–2 µs	already microsecond-scale
publisher-mutex wait	0 µs	already won; ~35× vs the before shape
reconcile / sweep cadences	1–300 s	cadence, not transaction latency — conflating the two makes "the system takes seconds" unfalsifiable

⚠ The correction that matters most

§4 of the issue named the 10 s command-publish retry budget as the p95 tail. It was wrong, and the way it was wrong is the reusable lesson.

The diagnosis was assembled from constants read in source — a 10 s deadline, 32 attempts, an exponential backoff — which supports a claim about what could happen. It was promoted to what was happening with no instrument that could say no.

server#393 shipped the fix for it, and the counter it added read:

noetl_ehdb_command_publish_deferred_total 0

Zero, across a full load run. The publish had always succeeded inside 500 ms. p95 stayed at 14.9 s.

A hazard visible in the source is not the same as the cost visible in production. The instrument is what separates them, and it should be built before the conclusion is published, not after.

server#393 remains a correct defensive change — it just fixes nothing that was happening.

What the tail actually was

emit_mirror measured 1.68 s mean on the request path, while every other phase was noise (emit_publish 50 ms, emit_should_publish 2 µs).

NOETL_EHDB_EVENTLOG_MIRROR_ASYNC=true was set and the queue was armed. Not enough:

queue_total{outcome="enqueued"}             2463
queue_total{outcome="enqueued_after_wait"}   327
queue_total{outcome="queue_full_inline"}     908    <- 24.6%

A quarter of all batches went back onto the request path. An inline batch waits out a 5 s enqueue timeout then POSTs with a 5 s timeout — up to 10 s — and a request emits three events.

The queue was not marginally behind: mean lag 170 s, only 56 of 2,790 batches draining within 10 s.

Cause: deliver_pass coalesced per execution and then POSTed strictly one at a time, so drain throughput was 1 / relay-round-trip regardless of how many independent executions waited — while the function's own comment already said different executions are independent.

It also explains the run-to-run bistability better than the issue's §5 did: queue fills → submits wait then go inline → requests slow → more in flight → queue stays full. A run stays under the knee or falls through it.

Recent activity

date	what	where
2026-09-02	Decomposition filed; P1/P2/P3 prioritised	#319
2026-09-03	P3 shipped (v3.100.3) — bounded on-path publish to 500 ms with a background continuation carrying the remaining deadline	server#393
2026-09-03	P3 measured and refuted; publish_deferred_total = 0, p95 unchanged	#319 comment
2026-09-03	P2 shipped — four catalog reads → one, no cache introduced	server#394
2026-09-03	P0 shipped — concurrent mirror drain (v3.100.4, live)	server#395

The validated curve — and what it says

Clean run on v3.100.4, 1/2/4/6/8/10 × 2 reps, nothing probing the server.

rep conc submit ok  err p50ms  p95ms  sched
1   1    46     46  0   120    2820   5s
1   2    46     46  0   140    11010  6s
1   4    20     8   12  30040  30080  6s
1   6    0      0   0   -      -      64s   <- SKIP, no generator scheduled
1   8    91     81  10  3430   30040  49s
1   10   36     7   29  30040  30050  54s
2   1    19     19  0   150    12050  6s
2   2    35     34  1   150    8000   6s
2   4    32     20  12  7550   30150  6s
2   6    18     0   18  30030  30110  6s
2   8    24     0   24  30040  30210  5s
2   10   102    84  18  7230   30030  49s

⚠⚠ Verdict: the bistability is NOT gone

c=8 goes 81 ok → 0 ok and c=10 goes 7 ok → 84 ok between two runs of the same configuration. That is the original cliff, unchanged in character. Only c≤2 is now consistently fast and clean.

⚠⚠ And the first "after" p95 was one rep

p95 14,910 → 3,070 ms at c=1 was published from a single sample; the repeat read 12,050 ms. One sample of a bimodal distribution reported as the distribution — the same mistake as §4, one level down. p50 is what is genuinely reproducible: 510 → 120/150 ms at c=1, 5,730 → 140/150 ms at c=2.

Run-wide deltas: inline fallback 24.6% → 8.3%, emit_mirror 1.68 → 0.78 s, lag 170 → 67 s. Everything ~2–3× better; nothing eliminated. The queue stayed pinned at depth 512 ten minutes after the load stopped, so the backlog outlives the traffic that made it.

The tail is now cleanly P1-bound. More drain concurrency cannot help: 8 parallel POSTs still land behind one writer taking ~4 ms fsync per append.

Next concrete steps

1. Fix two rig defects before the next capacity measurement. A SKIP row (0 0 0 with - latencies) reads like a total collapse at a glance; and levels run back-to-back with no drain interval, so each inherits the previous one's backlog — the two best rows both had ~50 s of Autopilot scheduling in front of them, which is free drain time. Neither number can be read as steady-state capacity until the queue settles between levels.
2. Tune the drain against the writer. DRAIN_MAX_BATCHES (more records coalesced per POST, hence fewer fsyncs) is the likelier lever than more concurrency, because the writer is the ceiling — but it risks the tier's page cap and needs measuring first.
3. P1 stays parked behind ehdb#322. The drain cannot outrun the writer it feeds, so ~4 ms/append bounds everything above it. Group-commit already exists in the engine (append_batch, one fsync per batch); adopting it is a durability trade, and that is the owner's decision, not an optimisation.

Decisions taken

• The 10 s publish deadline was not shortened. It exists to span a writer pod restart (~2.7 s measured, [#208]) and a dropped publish is lost — command.issued is durable but nothing reaches the bus, and there is no NATS after T5. Only the waiter moved.
• The mirror drain's concurrency is safe because of the queue's shape, not because ordering is unimportant: a pass holds at most one batch per execution_id, and pass N+1 does not start until pass N completes. NOETL_EHDB_EVENTLOG_MIRROR_DRAIN_CONCURRENCY=1 is the rollback.
• P2 introduced no cache. The row is read fresh every request; only the repeats were removed. A negative control fails the suite if content is ever retained, because a content cache would be faster still and serve stale playbooks.

Related

• ehdb#322 — the quorum-ack / durability decision P1 belongs with
• Umbrella: EHDB Primary Serve
• playbooks/load-test/ in noetl/ai-meta — the measurement rig, and the four harness artifacts it was built to remove