From 1bd3ea64dafa3bba7de039482dd05982c3e24cc5 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sat, 1 Aug 2026 07:51:52 -0500 Subject: [PATCH 1/2] =?UTF-8?q?backlog:=20file=20#320=20=E2=80=94=20window?= =?UTF-8?q?s-2025=20MLLP=20ingress=20is=20~10x=20slower=20than=20a=20healt?= =?UTF-8?q?hy=20runner?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Diagnosis only; no code change. The CI symptom was fixed in #115 (06fd327d) by widening the reconcile's stranding budget. This files the capacity fact that fix deliberately did not address. The load smoke offers 60 msg/s at a listener whose ingress is strictly serial per connection (mllp.py:1433 awaits the durable commit per frame), so total ingress is pool_size / commit-latency. On windows-2025 that is under 60/s. Reproduced the signature on a healthy box by raising the offered rate alone: 0% stranding at 60/s and at 300/s, then 50.7% at 600/s with engine_read 452 of 900 -- the same shape as windows-2025's 51.1% and 52 of 90 at 60/s. So that leg hits at 60/s what a healthy box hits at 600/s. Also corrects report.py's stated justification for the old budget: healthy stranding at this rate is 0%, not the "~16% worst seen" it cited, and "half" was ~1.0x that worst by the time it red main, not 3x. Records one adjacent unverified finding: at saturation engine_read cleared the unconditional `read >= sent // 2` floor by two messages, and a floor breach is a hard failure no budget widening can rescue. A 1200/s probe did not reproduce it but is not comparable (drain timed out, different code path). Co-Authored-By: Claude Opus 5 --- docs/BACKLOG.md | 30 ++++++++++++++++++++++++++++++ 1 file changed, 30 insertions(+) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 4c98d248..0d935dd6 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -7295,3 +7295,33 @@ So `calling_ae_allowlist` **alone** satisfies a gate whose stated purpose is to **Related:** ADR 0155, `.github/workflows/dast.yml`, `scripts/security/dast_auth_sweep.py`, `scripts/security/route_gates.py`, `scripts/security/dast-policy.json`, `tests/test_dast_auth_sweep.py`, `tests/test_dast_claims.py`, [`Secure_Development_Standards`](Secure_Development_Standards.md) ยง6.1 / ยงA.6. **Source:** the empty ยง6.1 *Dynamic* tier row, filed and built 2026-07-31. + +## 320. windows-2025 MLLP ingress is ~10x slower than a healthy runner + +> ๐Ÿ“‹ **Filed 2026-08-01, not started.** Diagnosis only โ€” the CI symptom is already fixed (#115, `06fd327d`) by widening the reconcile's stranding budget. This item is the **underlying capacity fact**, which that fix does not address and deliberately did not try to. + +**Type:** CI/runner capacity โ€” not a correctness defect. No message was ever lost in any observed instance. + +**What:** the `test (windows-2025, py3.14)` leg cannot service the load smoke's offered rate. `tests/test_load_runner.py` offers **60 msg/s for 1.5s** (90 messages, `pool_size = 4`) at a listener whose ingress is **strictly serial per connection** โ€” `mllp.py:1433` is `read chunk โ†’ for each frame โ†’ await handler โ†’ next`, where the handler is the durable ingress commit the ACK depends on. Total ingress throughput is therefore `pool_size รท per-message-commit-latency`. On windows-2025 that product is under 60/s, so roughly half the offered run is never ingested inside the measurement window and strands unacknowledged at teardown. + +**Measured (2026-08-01).** The same signature reproduces on a healthy developer box purely by raising the offered rate โ€” same profile, same code, same `run_load` path: + +| offered | sent | acked | stranded | engine_read | +|---|---|---|---|---| +| 60/s | 90 | 90 | **0 (0.0%)** | 90 | +| 300/s | 450 | 450 | **0 (0.0%)** | 450 | +| **600/s** | 900 | 444 | **456 (50.7%)** | **452** | + +windows-2025 observed at **60/s**: sent 90, acked 44, stranded 46 (**51.1%**), `engine_read` 52 โ€” the 600/s row, at one tenth the offered rate. **windows-2025 hits at 60/s what a healthy box hits at 600/s.** + +**Why it matters even though nothing is lost:** the same numbers recurred **byte-identically** on two different commits (`9b03057f`, `56f7d240` โ€” 90/44/46/52 both times), so this is deterministic queueing, not runner weather. It will recur on any profile whose offered rate approaches the leg's service rate, and it is invisible to a correctness check because delivery is complete (104 written, 104 received, backlog drained in 4.7s of a 30s bound). + +**Correcting the record:** `harness/load/report.py` previously justified the stranding budget with *"observed teardown stranding is ~16%, so half is ~3x the worst seen."* Both halves are wrong. **Healthy stranding at this rate is 0%**, not 16% โ€” the 16% figure was itself measured on a partially-saturated run โ€” and "half" was ~1.0x the worst seen by the time it red `main`, not 3x. + +**Not yet determined:** *why* that runner's per-message commit is ~10x slower. Disk/fsync characteristics of the hosted windows-2025 image, Defender scanning the temp SQLite DB, and CPU contention are all plausible; none has been measured, and it cannot be measured from outside the runner. + +**Adjacent finding, unverified:** at saturation `engine_read` (452) cleared the reconcile's unconditional anti-vacuity floor `read >= sent // 2` (450) by **two messages**. A breach of that floor is a hard failure no budget widening can rescue. A probe at 1200/s did *not* reproduce it, but that run is not comparable โ€” its drain timed out (`max_drain_seconds` observed `-1.0`) and it took the branch that skips the settle-poll. Untested, not disproven. + +**Related:** #115 (`06fd327d`, the budget fix), `harness/load/report.py` `_reconcile`, `harness/load/connscale/runner.py`, `harness/load/estate/runner.py`, `tests/test_load_runner.py`, `tests/test_harness_reconcile.py`, `messagefoundry/transports/mllp.py:1433`, and the sibling windows-2025 failure `test_coord_lock` (fixed in #109) โ€” a *different* mechanism on the same leg. + +**Source:** investigation of the `test_run_load_end_to_end_no_loss` failures on `main` at `9b03057f` and `56f7d240`, 2026-08-01. From ce13bdd8be70009c059fb63e324a44dc11aaf2a3 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sat, 1 Aug 2026 08:21:09 -0500 Subject: [PATCH 2/2] =?UTF-8?q?backlog:=20retract=20the=20#320=20reproduct?= =?UTF-8?q?ion=20=E2=80=94=20it=20was=20n=3D1=20on=20a=20contended=20box?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The first write-up claimed the windows-2025 signature reproduces on a healthy developer box by raising the offered rate alone, citing one 600/s run that stranded 456 of 900 (50.7%). Four repeats of the same command on the same box stranded 0, every time; the outlier was taken while an unrelated test suite ran concurrently. Withdrawn. Stranding on a developer box is a CONTENTION artifact, not a clean function of offered rate -- and drawing a conclusion from one run is the exact failure mode this item documents, committed while documenting it. The surviving claim is weaker and still actionable: an unloaded box strands ZERO at up to 10x the CI profile's rate, while windows-2025 stranded ~51% at the profile's own 60/s twice (9b03057f, 56f7d240) with byte-identical counters. Byte-identical repetition rules out weather ON THAT LEG; it says nothing about a developer box, and the retracted entry conflated the two. Also points at the probe + dispatch-only workflow now on ingress-rate-probe, whose --repeat exists so the next reader gets a distribution rather than a lucky row. Co-Authored-By: Claude Opus 5 --- docs/BACKLOG.md | 24 ++++++++++++++++-------- 1 file changed, 16 insertions(+), 8 deletions(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 0d935dd6..35520812 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -7304,17 +7304,25 @@ So `calling_ae_allowlist` **alone** satisfies a gate whose stated purpose is to **What:** the `test (windows-2025, py3.14)` leg cannot service the load smoke's offered rate. `tests/test_load_runner.py` offers **60 msg/s for 1.5s** (90 messages, `pool_size = 4`) at a listener whose ingress is **strictly serial per connection** โ€” `mllp.py:1433` is `read chunk โ†’ for each frame โ†’ await handler โ†’ next`, where the handler is the durable ingress commit the ACK depends on. Total ingress throughput is therefore `pool_size รท per-message-commit-latency`. On windows-2025 that product is under 60/s, so roughly half the offered run is never ingested inside the measurement window and strands unacknowledged at teardown. -**Measured (2026-08-01).** The same signature reproduces on a healthy developer box purely by raising the offered rate โ€” same profile, same code, same `run_load` path: +**Measured (2026-08-01), and one measurement RETRACTED โ€” read this before quoting a number.** -| offered | sent | acked | stranded | engine_read | -|---|---|---|---|---| -| 60/s | 90 | 90 | **0 (0.0%)** | 90 | -| 300/s | 450 | 450 | **0 (0.0%)** | 450 | -| **600/s** | 900 | 444 | **456 (50.7%)** | **452** | +The first write-up of this item claimed the CI signature reproduces on a healthy developer box purely by raising the offered rate, on the strength of a single 600/s run that stranded **456 of 900 (50.7%)** โ€” a near-exact match for windows-2025's 51.1%. **Four repeats of that same command on that same box then stranded 0, every time.** The outlier was taken while an unrelated test suite was running concurrently. + +So that reproduction is **withdrawn**. Stranding on a developer box is a **contention** artifact, not a clean function of offered rate, and n=1 is not a measurement โ€” which is exactly the failure mode this item is about, committed while documenting it. + +What the repeats support: + +| offered | runs | stranded | engine_read | +|---|---|---|---| +| 60/s | 1 | **0 (0.0%)** | 90 of 90 | +| 300/s | 1 | **0 (0.0%)** | 450 of 450 | +| 600/s | 5 | **0 in 4 runs**; 50.7% in the 1 contended run | ~899 of ~899 when unloaded | + +**The surviving claim is weaker and still worth acting on:** an unloaded box strands **zero** at up to 10ร— the CI profile's offered rate, while windows-2025 stranded ~51% at the profile's own **60/s** โ€” twice, on `9b03057f` and `56f7d240`, with **byte-identical** counters (90 sent / 44 acked / 46 stranded / 52 read). Byte-identical repetition is what rules out weather *on that leg*; it is not evidence about a developer box, and the earlier entry conflated the two. -windows-2025 observed at **60/s**: sent 90, acked 44, stranded 46 (**51.1%**), `engine_read` 52 โ€” the 600/s row, at one tenth the offered rate. **windows-2025 hits at 60/s what a healthy box hits at 600/s.** +**Why it matters even though nothing is lost:** it recurs, it will recur on any profile whose offered rate approaches that leg's service rate, and it is invisible to a correctness check because delivery is complete every time (104 written, 104 received, backlog drained in 4.7s of a 30s bound). -**Why it matters even though nothing is lost:** the same numbers recurred **byte-identically** on two different commits (`9b03057f`, `56f7d240` โ€” 90/44/46/52 both times), so this is deterministic queueing, not runner weather. It will recur on any profile whose offered rate approaches the leg's service rate, and it is invisible to a correctness check because delivery is complete (104 written, 104 received, backlog drained in 4.7s of a 30s bound). +**Tooling:** `harness/load/ingress_probe.py` + `.github/workflows/ingress-rate-probe.yml` (dispatch-only) now sweep the rate across ubuntu / windows-2022 / windows-2025 with `--repeat`, so the next person reads a distribution instead of a lucky row. **Correcting the record:** `harness/load/report.py` previously justified the stranding budget with *"observed teardown stranding is ~16%, so half is ~3x the worst seen."* Both halves are wrong. **Healthy stranding at this rate is 0%**, not 16% โ€” the 16% figure was itself measured on a partially-saturated run โ€” and "half" was ~1.0x the worst seen by the time it red `main`, not 3x.