Skip to content

Issue #251 solved: bound the mirror's send buffer so lag is detectable - #265

Open
PRINCEKK122 wants to merge 1 commit into
oss-slu:mainfrom
PRINCEKK122:251-bound-the-mirror-send-buffer
Open

PRINCEKK122 wants to merge 1 commit into
oss-slu:mainfrom
PRINCEKK122:251-bound-the-mirror-send-buffer

Conversation

@PRINCEKK122

Copy link
Copy Markdown
Contributor

Closes #251.

What was wrong

a_slow_python_reader_does_not_pace_imotions and a_python_process_that_stops_reading_is_dropped_not_waited_on fail on main. They fail on my machine and they fail on GitHub's runners (21 passed, 2 failed, same two assertions), so this is not one bad host.

My first read was that the tests were volume-dependent and needed a bigger sample count. That is wrong, and the measurements say why.

The actual cause

MIRROR_QUEUE_CAPACITY bounds the queue in front of the mirror's writer thread. Behind the writer, the socket's own send buffer is a second queue, and nothing bounded it. Measured on loopback with the packets the relay actually sends:

send / recv buffer absorbed before a write blocks 50k packets to a reader keeping up
host defaults 36,818 packets 0.055 s
snd 32 KiB, recv default 3,200 packets 0.044 s
snd 32 KiB, recv 2 KiB 494 packets 0.049 s

At 160 packets a second, the default buffers let the mirror run about 230 seconds behind before a write blocks. So MIRROR_WRITE_TIMEOUT never fires, mirror_send never sees a full queue, and the relay reports nothing. The 256-packet bound in front of the writer was decoration.

That is the ADR 0003 claim not holding: the relay is supposed to bound the backlog and say so, not buffer four minutes of stream silently. The tests were asserting the right thing.

The fix

Set SO_SNDBUF explicitly in connect_mirror. The hidden backlog drops from ~37,000 packets to ~3,200, about twenty seconds, and the table shows it costs no throughput. std::net does not expose the option, so socket2 is now a dependency — cross-platform, so the Windows build gets it too, and it compiles for x86_64-pc-windows-gnu.

The tests additionally pin a small SO_RCVBUF on their Python-side listener. In production that buffer belongs to the Python process and is whatever the host decided, so the tests should not depend on it. With both sides bounded the backpressure is real on any host, which lets the sample counts drop from 1500 and 3000 to 500 — the relay suite now runs in 0.42 s instead of 2.12 s.

Verification

  • 23/23 pass; main is 21/23
  • the two tests pass 25/25 consecutive runs
  • the full suite passes with 8 copies running concurrently under CPU contention
  • socket2 compiles for the Windows target
  • added lines are cargo fmt clean

Nothing here needs live X-Plane or iMotions.

Note for review

@Phlabry you wrote these tests and ADR 0003, so you are the right person to disagree with this. The issue reads as test flakiness and the fix changes production behaviour, which is a real scope increase — I went that way because the tests could not be made deterministic without bounding our own send buffer, and because a four-minute invisible backlog looked like a defect rather than a test problem. The numbers above are reproducible if you want to check the reasoning.

Pre-existing, not touched

  • cargo clippy fails on main at relay/src/state.rs:760 (never_loop on for message in … { match message {} }), deny-by-default
  • 68 cargo fmt --check diffs across the relay

…tectable

The two mirror tests asserted that a Python process which stops reading
gets dropped on the write timeout, and that a slow one is reported rather
than quietly coped with. Both failed on fast hosts and on GitHub's
runners, because neither condition could be reached.

The cause was not the tests. MIRROR_QUEUE_CAPACITY bounds the queue in
front of the mirror's writer thread, but the socket's send buffer behind
it is a second, much larger queue: 2.5 MB by default on Linux. Measured
on loopback, that and the reader's buffer absorb about 37,000 packets --
close to four minutes of stream at 160 packets a second -- before a write
blocks. So a mirror that stopped reading minutes ago still takes writes,
MIRROR_WRITE_TIMEOUT never fires, and the relay reports nothing. The
bound in front of the writer was decoration.

Set SO_SNDBUF explicitly on the mirror socket. That brings the hidden
backlog down to about 3,200 packets, or twenty seconds, and costs no
throughput: 50,000 packets to a reader that keeps up take the same 45 ms
either way. std::net does not expose the option, so socket2 is now a
dependency; it is cross-platform, so the Windows build gets it too.

The tests also pin a small SO_RCVBUF on their Python-side listener, since
the reader's buffer belongs to the Python process in production and is
whatever the host decided. With both sides bounded the backpressure is
real on any host, so the sample counts drop from 1500 and 3000 to 500 and
the suite runs in 0.42s instead of 2.12s.
@PRINCEKK122

Copy link
Copy Markdown
Contributor Author

CI evidence, from the Rust workflow in #253 (this PR cannot run it itself — that workflow file only exists on #253's branch):

Before, on plain main — https://github.com/oss-slu/PilotDataSynchronization/actions/runs/40808333057

test result: FAILED. 21 passed; 2 failed
failures:
    update::tests::a_python_process_that_stops_reading_is_dropped_not_waited_on
    update::tests::a_slow_python_reader_does_not_pace_imotions

After, with this branch underneath — https://github.com/oss-slu/PilotDataSynchronization/actions/runs/41191646149

Compiling socket2 v0.5.10
running 23 tests
test result: ok. 23 passed; 0 failed; 0 ignored; 0 measured; finished in 0.50s

Same runner, same OS, nothing else changed. socket2 built on ubuntu-latest with no extra system packages, and the relay build was unaffected (1m52s).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Two mirror tests from #247 fail on main on Linux

1 participant