Skip to content

Commit 57a8bab

Browse files
wshallwshallclaude
wshallwshall
and
claude
committed
harness: measure a runner's MLLP ingress rate instead of pass/failing one point
test_load_runner red the required windows-2025 leg twice on main (9b03057, 56f7d24) with byte-identical counters -- 90 sent, 44 acked, 46 stranded, 52 read -- on runs that lost nothing. #115 widened the reconcile's stranding budget so a saturated-but-lossless run stops failing. That fixed the symptom and said nothing about the cause, and a pass/fail test at ONE fixed offered rate structurally cannot: the question is whether windows-2025 is slow or windows is, and that is a rate, not a verdict. Adds `harness.load.ingress_probe` (sweeps offered rate, prints one machine- parseable RESULT line per run) and a workflow_dispatch-only workflow that runs it across ubuntu-latest / windows-2022 / windows-2025 and writes a side-by-side table to the step summary. ubuntu is the CONTROL: it establishes what "not saturated" looks like on hosted hardware so a slow Windows row can be read against it. REPEATS ARE THE POINT, and this is a correction to my own earlier claim. One 600/s run on a developer box produced 456 stranded of 900 (50.7%) -- a near-exact match for the windows-2025 CI signature -- and I wrote it up as a clean reproduction. Four repeats of the same command on the same box then produced 0 stranded, every time; the outlier was taken while an unrelated test suite was running. So stranding here is a CONTENTION artifact, not a clean function of offered rate, and n=1 is not a measurement. Hence --repeat, defaulted to 3, with the correction recorded in the module docstring so the next reader does not redo it. What survives that correction is the weaker, still-useful claim: 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, byte-identically. Deliberately NOT a required context and structurally unfit to become one: no pull_request trigger, and the probe exits 0 even when the reconcile fails, because a machine too slow to keep up is the finding rather than an error. Recorded in .github/required-contexts.txt with the other advisory workflows. Prints no derived per-second figure either -- engine_read/wall looks like a service rate and is not one (wall includes stop grace, drain and settle, so it lands at ~25/s whether the run offered 60/s or 600/s). Scope: both legs are hosted VMs, so a slow-2025/fast-2022 result narrows the cause to the 2025 IMAGE. It cannot clear or convict Windows Server 2025 as a deployment target -- only the self-hosted WS2025 rig can, and it was unregistered (actions/runners -> total_count 0) when this was written. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
1 parent 06fd327 commit 57a8bab

3 files changed

Lines changed: 307 additions & 0 deletions

File tree

‎.github/required-contexts.txt‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -115,6 +115,10 @@ a PR that implements BACKLOG #N must update BACKLOG.md
115115
# never report on a PR (required-but-absent trap). Advisory by
116116
# placement, not by continue-on-error: the job goes red on a finding.
117117
# See ADR 0155.
118+
# ingress-rate-probe.yml -- workflow_dispatch only, so it never reports on a PR. It is also
119+
# structurally unfit to gate anything: it MEASURES a runner's ingress
120+
# service rate and exits 0 even when the reconcile fails, because a
121+
# machine too slow to keep up is the finding, not an error. See #320.
118122
# freethread-smoke.yml -- a 3.14t canary; informational only.
119123
# manifest-lint.yml -- paths-filtered to the k8s manifests.
120124
# nightly / path-gated legs -- server-DB store, load/throughput, service-smoke, DICOM/FHIR

‎.github/workflows/ingress-rate-probe.yml‎

Lines changed: 105 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,105 @@
1+
# Measure the MLLP ingress service rate of each hosted runner SKU (#320).
2+
#
3+
# WHY THIS EXISTS. `test_load_runner::test_run_load_end_to_end_no_loss` red the required windows-2025
4+
# leg twice on `main` (9b03057f, 56f7d240) with byte-identical counters — 90 sent, 44 acked, 46
5+
# stranded, 52 read — on runs that lost nothing. #115 widened the reconcile's stranding budget so a
6+
# saturated-but-lossless run stops failing, which fixes the symptom and tells you nothing about the
7+
# cause. The open question is whether the windows-2025 IMAGE is slow or windows generally is, and a
8+
# pass/fail test at one fixed rate structurally cannot answer it. This sweeps the rate and reports the
9+
# stranded fraction on each SKU, side by side.
10+
#
11+
# WHAT IT CANNOT ANSWER. Both legs here are GitHub-hosted VMs. If 2025 is slow and 2022 is not, that
12+
# narrows the cause to the 2025 image — it does NOT convict Windows Server 2025 as a deployment
13+
# target, because a hosted image can be slow for reasons a deployed server is not (Defender policy,
14+
# VM disk backing, noisy neighbours). Only the self-hosted WS2025 rig can settle that, and it was
15+
# unregistered (`actions/runners` → total_count 0) when this was written. See BACKLOG #320.
16+
#
17+
# DELIBERATELY workflow_dispatch ONLY, and deliberately NOT a required context. It has no
18+
# `pull_request` trigger, so it can never report on a PR and can never become the required-but-absent
19+
# trap; it is listed in `.github/required-contexts.txt` alongside the other advisory workflows. It also
20+
# ASSERTS NOTHING — the probe exits 0 even when the reconcile fails, because a machine too slow to keep
21+
# up is the finding, not an error. A number that moves with runner weather must never gate a merge.
22+
#
23+
# REPEATS ARE NOT OPTIONAL. A single run proves nothing: one 600/s run on a developer box produced
24+
# 50.7% stranding and four repeats of the same command produced 0%, the difference being an unrelated
25+
# test suite running concurrently. Default 3 repeats per rate; read the spread, not any one row.
26+
name: ingress rate probe
27+
28+
on:
29+
workflow_dispatch:
30+
inputs:
31+
rates:
32+
description: "Comma-separated offered rates in msg/s (the CI load smoke offers 60)"
33+
default: "60,150,300,600"
34+
type: string
35+
repeat:
36+
description: "Runs per rate. Never conclude from 1 — see the header."
37+
default: "3"
38+
type: string
39+
40+
# Read-only: this builds nothing, publishes nothing, and touches no secret.
41+
permissions:
42+
contents: read
43+
44+
concurrency:
45+
# A rate measurement taken while a second copy of itself is running measures the contention, not the
46+
# runner. Queue, never cancel — a half-finished sweep is worse than a late one.
47+
group: ingress-rate-probe
48+
cancel-in-progress: false
49+
50+
jobs:
51+
probe:
52+
name: ingress rate (${{ matrix.os }})
53+
runs-on: ${{ matrix.os }}
54+
timeout-minutes: 45
55+
strategy:
56+
fail-fast: false # one slow SKU must not cancel the comparison it exists to provide
57+
matrix:
58+
# ubuntu is the CONTROL, not a deployment target: it is the fastest leg and establishes what
59+
# "not saturated" looks like on hosted hardware, so a slow Windows row can be read against it.
60+
os: [ubuntu-latest, windows-2022, windows-2025]
61+
steps:
62+
- uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1 # v7.0.1
63+
with:
64+
persist-credentials: false
65+
66+
- name: Set up uv
67+
uses: astral-sh/setup-uv@c771a70e6277c0a99b617c7a806ffedaca235ff9 # v9.0.0
68+
69+
- name: Set up Python 3.14
70+
uses: actions/setup-python@5fda3b95a4ea91299a34e894583c3862153e4b97 # v7.0.0
71+
with:
72+
python-version: "3.14"
73+
74+
- name: Install project (dev extras only — the probe needs the engine and the harness)
75+
run: uv pip install --system --constraint constraints.lock -e ".[dev]"
76+
77+
- name: Sweep
78+
shell: bash
79+
env:
80+
# Hoisted, never interpolated into the script body (zizmor: template injection).
81+
RATES: ${{ inputs.rates }}
82+
REPEAT: ${{ inputs.repeat }}
83+
OS_LABEL: ${{ matrix.os }}
84+
run: |
85+
set -uo pipefail # NOT -e: a probe that cannot start must not lose the rows already taken
86+
echo "## ingress rate probe — $OS_LABEL" >> "$GITHUB_STEP_SUMMARY"
87+
echo "" >> "$GITHUB_STEP_SUMMARY"
88+
echo "| offered | sent | acked | stranded | % | engine_read | reconcile ok |" >> "$GITHUB_STEP_SUMMARY"
89+
echo "|---|---|---|---|---|---|---|" >> "$GITHUB_STEP_SUMMARY"
90+
IFS=',' read -ra RATE_LIST <<< "$RATES"
91+
for rate in "${RATE_LIST[@]}"; do
92+
rate="$(echo "$rate" | tr -d '[:space:]')"
93+
[ -n "$rate" ] || continue
94+
echo "::group::rate ${rate}/s x ${REPEAT}"
95+
python -m harness.load.ingress_probe "$rate" --repeat "$REPEAT" 2>&1 | tee /tmp/probe.out
96+
echo "::endgroup::"
97+
grep '^RESULT' /tmp/probe.out | while read -r line; do
98+
# Parse the k=v pairs the probe emits; missing keys render as "?" rather than breaking.
99+
eval "$(echo "$line" | tr ' ' '\n' | grep '=' | sed 's/^/P_/')" 2>/dev/null || true
100+
echo "| ${P_rate:-?}/s | ${P_sent:-?} | ${P_acked:-?} | ${P_stranded:-?} | ${P_pct:-?}% | ${P_read:-?} | ${P_ok:-?} |" >> "$GITHUB_STEP_SUMMARY"
101+
unset P_rate P_sent P_acked P_stranded P_pct P_read P_ok
102+
done
103+
done
104+
echo "" >> "$GITHUB_STEP_SUMMARY"
105+
echo "_Repeats per rate: ${REPEAT}. Read the spread — a single row is not a measurement (BACKLOG #320)._" >> "$GITHUB_STEP_SUMMARY"

‎harness/load/ingress_probe.py‎

Lines changed: 198 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,198 @@
1+
# SPDX-License-Identifier: AGPL-3.0-or-later
2+
# Copyright (C) 2026 MessageFoundry Organization and contributors
3+
"""Measure the MLLP ingress SERVICE RATE of the machine this runs on (#320).
4+
5+
THE QUESTION THIS EXISTS FOR. `test_load_runner::test_run_load_end_to_end_no_loss` red the required
6+
windows-2025 leg twice on `main` (9b03057f, 56f7d240) with byte-identical counters -- 90 sent, 44
7+
acked, 46 stranded, 52 read -- on runs that lost nothing. The reconcile's stranding budget was widened
8+
(#115) so a saturated-but-lossless run stops failing, but that treats the symptom: the leg saturates at
9+
an offered rate a healthy box absorbs ten times over, and *pass/fail on one fixed rate cannot tell you
10+
that*. This probe reports the rate itself.
11+
12+
WHAT SATURATION LOOKS LIKE, AND WHY IT IS NOT LOSS. The listener ingests strictly serially per
13+
connection (`messagefoundry/transports/mllp.py`: read chunk -> for each frame -> await the durable
14+
commit -> next), so total ingress is ``pool_size / commit-latency``. Offer more than that and the
15+
excess is still in the client's socket when the phase ends; those sends are counted UNCONFIRMED, never
16+
lost -- everything the engine did ingest is delivered and reconciles clean. So the honest signal of
17+
"this machine cannot keep up" is the stranded FRACTION at a known offered rate, not a verdict.
18+
19+
ALWAYS REPEAT. A SINGLE RUN PROVES NOTHING -- this was learned the expensive way. On 2026-08-01 one
20+
600/s run on a developer box produced 456 stranded of 900 (50.7%), a near-exact match for the
21+
windows-2025 CI signature, and it was written up as a clean reproduction. Four repeats of the SAME
22+
command on the SAME box then produced **0 stranded, every time**:
23+
24+
60/s x1 -> 90 sent, 90 acked, 0 stranded (0.0%), 90 read
25+
300/s x1 -> 450 sent, 450 acked, 0 stranded (0.0%), 450 read
26+
600/s x5 -> ~899 sent, 0 stranded in 4 runs; 456 stranded (50.7%) in the 1 run taken while the
27+
machine was busy with an unrelated test suite
28+
29+
So stranding here is a CONTENTION artifact, not a clean function of offered rate: the outlier was the
30+
machine being loaded, which is exactly the "runner weather" this probe exists to characterise. Hence
31+
``--repeat``: report the distribution, and never draw a conclusion from n=1. What survives that
32+
correction is only the weaker, still-useful claim -- an unloaded machine strands ZERO at rates up to
33+
10x the CI profile's, while windows-2025 stranded ~51% at the profile's own 60/s, twice, with
34+
byte-identical counters.
35+
36+
WHAT SATURATION IS NOT. Stranded sends are UNCONFIRMED, never lost: everything the engine ingested is
37+
delivered and reconciles clean. The signal is the stranded FRACTION at a known offered rate, not a
38+
verdict.
39+
40+
NOT A BENCHMARK, AND NOT A GATE. One short phase on SQLite in a temp dir; it answers "can this machine
41+
service N msg/s through 4 connections", nothing about production capacity. It is `workflow_dispatch`
42+
only and asserts nothing -- a number that varies with runner weather must never gate a merge.
43+
44+
Usage: python -m harness.load.ingress_probe <rate> [--repeat N] [--duration S] [--pool N]
45+
"""
46+
47+
from __future__ import annotations
48+
49+
import asyncio
50+
import os
51+
import socket
52+
import sys
53+
import tempfile
54+
import threading
55+
import time
56+
from pathlib import Path
57+
58+
import uvicorn
59+
60+
from harness.load.profile import load_profile_text
61+
from harness.load.runner import run_load
62+
63+
_CONFIG_DIR = Path("harness/config/load")
64+
_START_TIMEOUT_S = 15.0
65+
66+
67+
def _reserve() -> socket.socket:
68+
"""A bound-but-unlistened loopback socket, kept open so the OS cannot re-hand the port.
69+
70+
Mirrors tests/test_load_runner.py's `_reserve_port`: closing a socket just to learn its number
71+
opens a window where a contended runner reassigns it before the real server binds.
72+
"""
73+
s = socket.socket()
74+
s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
75+
s.bind(("127.0.0.1", 0))
76+
return s
77+
78+
79+
def _profile(*, adt_port: int, rate: float, duration_s: float, pool_size: int) -> object:
80+
return load_profile_text(f"""
81+
[load]
82+
name = "ingress-probe"
83+
pool_size = {pool_size}
84+
poll_interval_s = 0.25
85+
drain_timeout_s = 30.0
86+
[[load.target]]
87+
name = "adt_hub"
88+
host = "127.0.0.1"
89+
port = {adt_port}
90+
types = ["ADT"]
91+
[load.mix]
92+
"ADT^A05" = 1.0
93+
[load.slo]
94+
zero_loss = true
95+
max_drain_seconds = 30.0
96+
[[load.phase]]
97+
name = "steady"
98+
kind = "sustained"
99+
loop = "open"
100+
rate_start = {rate}
101+
duration_s = {duration_s}
102+
""")
103+
104+
105+
def probe(rate: float, duration_s: float = 1.5, pool_size: int = 4) -> int:
106+
"""Run one phase at ``rate`` and print a single machine-parseable RESULT line."""
107+
tmp = tempfile.mkdtemp(prefix="mefor-ingress-probe-")
108+
adt_s, res_s, oth_s, sink_s, api_s = (_reserve() for _ in range(5))
109+
adt_port, sink_port, api_port = (
110+
adt_s.getsockname()[1],
111+
sink_s.getsockname()[1],
112+
api_s.getsockname()[1],
113+
)
114+
os.environ.update(
115+
MEFOR_LOAD_FANOUT="2",
116+
MEFOR_LOAD_RESULTS_FANOUT="1",
117+
MEFOR_LOAD_TRANSFORM="cheap",
118+
MEFOR_LOAD_ADT_PORT=str(adt_port),
119+
MEFOR_LOAD_RESULTS_PORT=str(res_s.getsockname()[1]),
120+
MEFOR_LOAD_OTHER_PORT=str(oth_s.getsockname()[1]),
121+
MEFOR_LOAD_SINK_PORT=str(sink_port),
122+
)
123+
from messagefoundry.api import create_managed_app
124+
125+
app = create_managed_app(
126+
db_path=Path(tmp) / "probe.db", config_dir=_CONFIG_DIR, poll_interval=0.05
127+
)
128+
uv = uvicorn.Server(uvicorn.Config(app, host="127.0.0.1", port=api_port, log_level="error"))
129+
# Release the MLLP ports at the last moment; hand the still-bound API socket to uvicorn.
130+
for s in (adt_s, res_s, oth_s, sink_s):
131+
s.close()
132+
threading.Thread(target=lambda: uv.run(sockets=[api_s]), daemon=True).start()
133+
deadline = time.time() + _START_TIMEOUT_S
134+
while not uv.started:
135+
time.sleep(0.05)
136+
if time.time() > deadline:
137+
print(f"RESULT rate={rate:g} ERROR=engine_did_not_start", flush=True)
138+
return 2
139+
140+
t0 = time.perf_counter()
141+
report = asyncio.run(
142+
run_load(
143+
_profile(adt_port=adt_port, rate=rate, duration_s=duration_s, pool_size=pool_size), # type: ignore[arg-type]
144+
engine_url=f"http://127.0.0.1:{api_port}",
145+
id_prefix="PROBE1",
146+
sink_port=sink_port,
147+
db_backend="sqlite",
148+
)
149+
)
150+
wall = time.perf_counter() - t0
151+
c, nl = report.counters, report.no_loss
152+
pct = (c.timeouts / c.sent * 100.0) if c.sent else 0.0
153+
# NO derived per-second figure is printed. `engine_read / wall` looks like a service rate and is
154+
# not one: `wall` includes the stop grace, the drain and the settle-poll, so it lands at ~25/s
155+
# whether the run offered 60/s or 600/s. Report what was measured -- offered, ingested, stranded
156+
# -- and let the reader compare across rows.
157+
print(
158+
f"RESULT rate={rate:g} sent={c.sent} acked={c.acked} stranded={c.timeouts} "
159+
f"pct={pct:.1f} read={nl.engine_read} written={nl.engine_written} "
160+
f"sink={nl.sink_received} backlog={nl.backlog} ok={nl.ok} wall={wall:.2f}",
161+
flush=True,
162+
)
163+
# Deliberately exit 0 even on a reconcile failure: this is a MEASUREMENT, not a gate. A machine
164+
# too slow to keep up is the finding, not an error, and a non-zero exit here would turn runner
165+
# weather into a red workflow.
166+
return 0
167+
168+
169+
def main(argv: list[str] | None = None) -> int:
170+
args = list(sys.argv[1:] if argv is None else argv)
171+
if not args:
172+
print(__doc__)
173+
return 2
174+
rate = float(args[0])
175+
repeat, duration_s, pool_size = 1, 1.5, 4
176+
i = 1
177+
while i < len(args):
178+
flag = args[i]
179+
value = args[i + 1] if i + 1 < len(args) else ""
180+
if flag == "--repeat":
181+
repeat = int(value)
182+
elif flag == "--duration":
183+
duration_s = float(value)
184+
elif flag == "--pool":
185+
pool_size = int(value)
186+
else:
187+
print(f"unknown option {flag!r}", file=sys.stderr)
188+
return 2
189+
i += 2
190+
for _ in range(repeat):
191+
rc = probe(rate, duration_s, pool_size)
192+
if rc != 0:
193+
return rc
194+
return 0
195+
196+
197+
if __name__ == "__main__":
198+
raise SystemExit(main())

0 commit comments

Comments
 (0)