diff --git a/CHANGELOG-INTERNAL.md b/CHANGELOG-INTERNAL.md index 7d3df9a..e0892c3 100644 --- a/CHANGELOG-INTERNAL.md +++ b/CHANGELOG-INTERNAL.md @@ -42,6 +42,70 @@ a `### BREAKING` section placed FIRST in that version, and each such line is pre - Help text and the flag tables in both READMEs now state that the flag is valid on its own. - Version bump deliberately NOT taken (convention 34): the owner closes it in `VERSION.txt`. +### Fixed: the injector asks Windows for a fine timer tick, and for it to be honoured (audit F3) + +`_inject_loop` holds a delayed packet with `Condition.wait(timeout=...)`, and Windows rounds that +timeout UP to the system timer tick - 15.6 ms unless the process asks for better. That rounding +was the entire added-latency error. Measured on the REAL capture path (ping through live +WinDivert, `--dst-ip 8.8.8.8`, two independent runs): a **constant +12.6 ms of round-trip +overshoot, independent of the setting** - +12.2 ms at `--latency 10` and +12.8 ms at `--latency +50`, where a proportional error would have been ~62 ms at the higher setting. The control run at +`--latency 0` measured +0.4 and -0.3 ms, so it was not the capture path, the driver or the link. + +`BeanEngine.start()` now takes a fine tick for the life of the SESSION and `_stop_locked` gives it +back after the injector thread is joined; `winenv.request_fine_timers` / `release_fine_timers` are +the (Windows-only, no-op elsewhere) wrappers. Session-scoped rather than process-scoped: the pair +costs ~1.3 us (measured), so nothing needs to hold a finer tick while the tool sits idle. + +**Two things this cost, both found by measuring rather than by reading docs:** + +* **`timeBeginPeriod` alone is a fix that works and then stops.** Windows 11 throttles a + BACKGROUND process's timer resolution: the request kept returning success with a perfectly + balanced request/release log, while the effect vanished after roughly ten seconds - in one + process, `Condition.wait(10 ms)` went 10.1, 10.3, then 15.6 ms for every later session. This + tool lives in the background (start a session, switch to the app under test), so shipping only + the obvious call would have regressed silently on users while measuring clean here. + `winenv._allow_fine_timers_in_background()` opts out via `SetProcessInformation` + (`ProcessPowerThrottling` + `PROCESS_POWER_THROTTLING_IGNORE_TIMER_RESOLUTION`, state 0), once + per process. With it, the same wait held 10.1-10.7 ms across 40 s of sampling and across eight + back-to-back sessions. +* **Querying the system-wide resolution proves nothing.** `NtQueryTimerResolution` reported a + current tick of 1.0 ms - something else on the machine was holding it - while our own waits were + still being rounded to 15.6 ms, because since Windows 10 2004 the tick is per-process. A session + that checks the global number and concludes "the timer is already fine" is reading a number that + does not apply to it. That is written into the `request_fine_timers` docstring. + +Result through the engine, eight sessions in one process (sparse traffic, the case the audit +measured at +8.3 ms): overshoot **+0.22 to +0.55 ms**, worst case down from ~25 ms to ~11 ms. + +**Accepted on the real capture path** (ping, 40 packets per setting, live WinDivert): + + krok nominal min p50 p90 max nadwyzka p50 (przed) + latency 10 45 45 46 50 61 +1 ms +12.6 ms + latency 50 125 125 126 130 135 +1 ms +12.6 ms + baseline 25 24 25 28 112 + +Same +1 ms at both settings, so the surcharge is gone rather than scaled; p90 is +5 ms at both. +Two measurement lessons worth keeping, because the first acceptance run (10 packets per setting) +read as a HALF fix at +6.3 / +9.5 ms: + +* **Average over ten pings is the wrong statistic here.** About 1% of packets sit in a tail, a ping + carries two impaired packets, and one outlier moves a ten-sample mean by 4-8 ms. The median was + right all along - the ten-sample run's own minima were already exactly nominal (45 and 125). +* **The tail is the LINK, not us.** In the 40-packet run the untouched baseline produced the worst + outlier of the whole session (max 112 ms, against 61 and 135 with the tool in the path). An + earlier reading that blamed a "worse tail" on this change did not survive a bigger sample. + +New tests in `tests/test_failsafe.py`: +`test_the_fine_timer_request_is_balanced_on_every_session_path` (clean stop, double stop, second +session and a start that raises - an unbalanced pair is invisible from inside the program, it just +means the process keeps a finer system timer for life), `test_a_refused_fine_timer_request_is_never +_released` (releasing one we never took decrements somebody else's refcount), +`test_the_background_timer_opt_out_is_asked_for_once_per_process` and +`test_the_fine_timer_calls_are_safe_to_make_anywhere`. The first two were verified by mutation: +dropping the release turns the first red with `['request']`, releasing unconditionally turns the +second red with `['request', 'release']`. + ### Fixed: a dropped packet no longer revives the NAT mapping it was dropped for (audit F1) `BeanCore.decide()` step 3 read and wrote the activity stamp in one `_FlowTable.touch()`, so the diff --git a/CHANGELOG.md b/CHANGELOG.md index 4ca13d9..b1813f9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -36,6 +36,18 @@ The format follows [Keep a Changelog](https://keepachangelog.com/); versions fol ### Fixed +- **The delay you set is the delay you get.** Every configured delay used to arrive with several + milliseconds of padding on top, because of how Windows rounds up the wait the tool uses to hold + a packet back. It was a fixed surcharge rather than a percentage, so it barely showed at 100 ms + and swamped the small settings: with the tool asked for 10 ms, a ping measured about 12.6 ms of + extra round trip on top of the expected amount, and asking for 1 ms produced roughly seven times + that. Simulating a fast LAN, a game server or a VoIP hop is exactly where that hurt. The tool now + asks Windows for a fine-grained timer while a session runs, and gives it back at STOP. Measured + with a plain `ping`, 40 packets per setting: asking for 10 ms of delay now costs 1 ms more than + it should instead of 12.6 ms, and asking for 50 ms costs the same 1 ms more - the surcharge is + gone rather than merely smaller. Jitter benefits the same way: variation below about 15 ms used + to disappear into the timer's own noise. + - **"NAT mapping expiry" now really cuts the incoming direction, instead of losing one packet every few seconds.** This impairment is there to answer one question: does the application notice its mapping is gone and send something to re-open it? It could not answer that. The diff --git a/beantester/engine.py b/beantester/engine.py index 3efa238..e376e2b 100644 --- a/beantester/engine.py +++ b/beantester/engine.py @@ -30,6 +30,7 @@ import weakref from . import portmap +from . import winenv from .core import BeanCore from .i18n import T from .scenario_runner import ScenarioRunner @@ -107,6 +108,10 @@ def __init__(self, log_fn=lambda *_: None): # poller. See _start_socketwatch. Targeting resolves against it whenever a # session has one - the choice is made in _targeting_table(). self._socketwatch = None + # True while this session holds a fine Windows timer tick (see start()). + # Tracked rather than released blindly: the OS refcounts the requests per + # process, so releasing one we were never granted unbalances the count. + self._fine_timers = False self.stop_reason = None # "user" | "duration" | "fault" | "exit" self.fault = None # last fatal worker error, if any self.reset_stats() @@ -584,6 +589,16 @@ def _start_locked(self, filt, divert, duration, socket_source=None): # tests this tool is aimed at) left a "running" engine holding an open divert # that NOTHING would ever close: the exact fail-open hole convention 20 forbids. _LIVE_ENGINES.add(self) + # Ask Windows for a fine timer tick, for the life of the SESSION. The + # injector releases a delayed packet by waiting on a Condition with a + # timeout, and Windows rounds such a timeout up to the system tick, so + # without this the tool overshoots every configured delay by up to a tick + # (measured: a 10 ms setting delivered at a median of 18.3 ms). Taken here + # rather than at import so an idle program holds nothing; released in + # _stop_locked, AFTER the injector thread has been joined. See + # winenv.request_fine_timers for why querying the system-wide resolution + # instead would be reading the wrong number. + self._fine_timers = winenv.request_fine_timers() try: # The live socket-event map (2b/2c): created FIRST, so the initial # targeting resolve below already reads it instead of the poller. @@ -785,6 +800,13 @@ def _stop_locked(self, reason): t.join(timeout=2.0) self._t_cap = self._t_inj = self._t_wd = None self._divert = None + # After the join, because the injector is what the fine tick is for. Only + # when this session was actually granted one: these are refcounted per + # process, so a release we never took would let a later, real request be + # cancelled by somebody else's stop. + if self._fine_timers: + self._fine_timers = False + winenv.release_fine_timers() with self._cv: discarded = len(self._heap) self._heap.clear() diff --git a/beantester/winenv.py b/beantester/winenv.py index 14b8b1c..f8408ab 100644 --- a/beantester/winenv.py +++ b/beantester/winenv.py @@ -105,6 +105,118 @@ def detach_console(): return ok +# The finest tick the timeBeginPeriod API accepts, and the one the injector wants. +TIMER_PERIOD_MS = 1 + +# Windows 11 throttles a BACKGROUND process's timer resolution request unless the +# process opts out (see _allow_fine_timers_in_background). Done once per process. +_TIMER_OPT_OUT = [None] + +_PROCESS_POWER_THROTTLING = 4 # PROCESS_INFORMATION_CLASS +_IGNORE_TIMER_RESOLUTION = 0x4 # PROCESS_POWER_THROTTLING_IGNORE_TIMER_RESOLUTION + + +def _allow_fine_timers_in_background(): + """Tell Windows to honour our timer request even when we are not in front. + + Without this, ``timeBeginPeriod`` on Windows 11 is a fix that WORKS ON THE + DEVELOPER'S MACHINE AND THEN STOPS. Measured here: the request kept being + granted (return code 0, request/release perfectly balanced) while the effect + quietly went away after roughly ten seconds - ``Condition.wait(10 ms)`` went + 10.1, 10.3, then back to 15.6 ms for every later session in the same process. + That is the OS declining to honour a background process's request, and this + tool spends its whole working life in the background: the tester starts a + session and switches to the application under test. + + With the opt-out the same wait stayed at 10.1-10.7 ms across 40 s of sampling. + + Called once per process; the policy costs nothing while we are not asking for + a fine tick, so there is nothing to undo. Fails harmlessly on Windows older + than 10 1709, which had no such throttling to opt out of. + """ + if _TIMER_OPT_OUT[0] is not None: + return _TIMER_OPT_OUT[0] + _TIMER_OPT_OUT[0] = False + if not is_windows(): + return False + try: + import ctypes + from ctypes import wintypes + + class _PowerThrottlingState(ctypes.Structure): + _fields_ = [("Version", wintypes.ULONG), + ("ControlMask", wintypes.ULONG), + ("StateMask", wintypes.ULONG)] + + kernel32 = ctypes.WinDLL("kernel32", use_last_error=True) + kernel32.SetProcessInformation.argtypes = [wintypes.HANDLE, ctypes.c_int, + ctypes.c_void_p, wintypes.DWORD] + kernel32.SetProcessInformation.restype = wintypes.BOOL + # ControlMask says which policy we are setting, StateMask=0 says "do NOT + # ignore my timer resolution" - i.e. honour it in the background too. + state = _PowerThrottlingState(1, _IGNORE_TIMER_RESOLUTION, 0) + _TIMER_OPT_OUT[0] = bool(kernel32.SetProcessInformation( + kernel32.GetCurrentProcess(), _PROCESS_POWER_THROTTLING, + ctypes.byref(state), ctypes.sizeof(state))) + except Exception as _exc: + crashlog.note(_exc, "winenv") + return _TIMER_OPT_OUT[0] + + +def request_fine_timers(period_ms=TIMER_PERIOD_MS): + """Ask Windows for a fine timer tick. True when granted (Windows only). + + ``BeanEngine`` holds a delayed packet by waiting on a Condition with a + timeout, and on Windows such a timeout is rounded UP to the system timer + tick - 15.6 ms unless THIS process asks for better. That rounding is the + whole of the added-latency error: measured on Win11 / CPython 3.14, + ``Condition.wait(1 ms)`` took a median of 15.56 ms, and the engine overshot a + configured 10 ms of latency by a median of 8.30 ms. + + **Reading the system-wide resolution proves nothing here.** Since Windows 10 + 2004 the tick is per-process: this machine was already running a 1.0 ms tick + (``NtQueryTimerResolution`` said so - something else had asked for it) while + our waits were still being rounded to 15.6 ms. A future session that queries + the global value and concludes "the timer is already fine" would be reading a + number that does not apply to us. Only asking changes anything: after + ``timeBeginPeriod(1)`` the same wait took 1.51 ms and the engine's overshoot + fell to 0.54 ms. + + The OS refcounts these per process, so every request MUST be matched by a + :func:`release_fine_timers`. The call costs ~1.3 us for the pair (measured), + so it belongs to the session, not to the process: nothing holds a finer tick + while the tool sits idle. + """ + if not is_windows(): + return False + # Order matters only in that the opt-out has to be in place for the request to + # be honoured; it is a process-wide policy, so it is set once and left alone. + _allow_fine_timers_in_background() + try: + import ctypes + return ctypes.WinDLL("winmm").timeBeginPeriod(int(period_ms)) == 0 + except Exception as _exc: + crashlog.note(_exc, "winenv") + return False + + +def release_fine_timers(period_ms=TIMER_PERIOD_MS): + """Give back one :func:`request_fine_timers`. Call ONLY for a granted request. + + Unbalanced calls are how a process ends up holding a fine tick for its whole + life (or giving back one it never took), so the caller tracks whether the + request was granted rather than releasing blindly. + """ + if not is_windows(): + return False + try: + import ctypes + return ctypes.WinDLL("winmm").timeEndPeriod(int(period_ms)) == 0 + except Exception as _exc: + crashlog.note(_exc, "winenv") + return False + + def set_dpi_awareness(): """Mark the process DPI-aware BEFORE the Tk root exists. diff --git a/tests/test_failsafe.py b/tests/test_failsafe.py index f7c523f..5b6c794 100644 --- a/tests/test_failsafe.py +++ b/tests/test_failsafe.py @@ -246,6 +246,108 @@ def flaky_start(self, *a, **k): recover.closed is True) +def _count_timer_calls(monkeypatch, granted=True): + """Replace the winenv timer calls with counters; returns the call log.""" + from beantester import engine as engine_mod + + calls = [] + monkeypatch.setattr(engine_mod.winenv, "request_fine_timers", + lambda *a, **k: calls.append("request") or granted) + monkeypatch.setattr(engine_mod.winenv, "release_fine_timers", + lambda *a, **k: calls.append("release") or True) + return calls + + +def test_the_fine_timer_request_is_balanced_on_every_session_path(monkeypatch): + """A granted fine timer tick MUST be given back - clean stop, double stop and + failed start alike. + + ``timeBeginPeriod`` is refcounted BY THE OS, per process, and an unbalanced pair + is invisible from inside the program: it just means this process keeps a finer + system timer for the rest of its life. Nothing would ever report that, which is + why the balance gets a test rather than a comment. + """ + import threading + + calls = _count_timer_calls(monkeypatch) + eng = BeanEngine() + eng.start("test", divert=QuietDivert()) + eng.stop() + eng.stop() # idempotent: the second stop releases nothing + check("fine timers: one request and one release per session", + calls == ["request", "release"], f"({calls})") + + eng.start("test", divert=QuietDivert()) + eng.stop() + check("fine timers: the next session is balanced too", + calls == ["request", "release"] * 2, f"({calls})") + + # ...and a start that blows up half way must not walk off with the tick either + real_start = threading.Thread.start + attempts = {"n": 0} + + def flaky_start(self, *a, **k): + attempts["n"] += 1 + if attempts["n"] > 1: + raise RuntimeError("can't start new thread") + return real_start(self, *a, **k) + + monkeypatch.setattr(threading.Thread, "start", flaky_start) + try: + eng.start("test", divert=QuietDivert()) + except RuntimeError: + pass + monkeypatch.undo() + check("fine timers: a failed start gives the tick back", + calls == ["request", "release"] * 3, f"({calls})") + + +def test_a_refused_fine_timer_request_is_never_released(monkeypatch): + """Off Windows (or with winmm missing) the request is refused - and then there + is nothing to give back. Releasing one we never took decrements a refcount that + belongs to somebody else, which would cancel THEIR fine timer.""" + calls = _count_timer_calls(monkeypatch, granted=False) + eng = BeanEngine() + eng.start("test", divert=QuietDivert()) + eng.stop() + check("fine timers: a refused request is not released", + calls == ["request"], f"({calls})") + + +def test_the_background_timer_opt_out_is_asked_for_once_per_process(monkeypatch): + """The opt-out is a process-wide POLICY, not a per-session request. + + It is also the part that makes the fine timer survive: without it Windows 11 + keeps granting ``timeBeginPeriod`` while quietly ceasing to honour it once the + process is no longer in front - which is where this tool lives, since the + tester starts a session and switches to the application under test. Measured + before it was added: the third and every later session in one process was back + to a 15.6 ms tick with a perfectly balanced request/release log. + """ + from beantester import winenv + + monkeypatch.setattr(winenv, "_TIMER_OPT_OUT", [None]) + winenv._allow_fine_timers_in_background() + winenv._TIMER_OPT_OUT[0] = "already answered" + again = winenv._allow_fine_timers_in_background() + check("timer opt-out: the answer is memoised, not asked for again", + again == "already answered", f"({again!r})") + + +def test_the_fine_timer_calls_are_safe_to_make_anywhere(): + """They run on every session start/stop, on every platform, so they may never + raise - and off Windows there is nothing to ask for.""" + from beantester import winenv + + granted = winenv.request_fine_timers() + if granted: + winenv.release_fine_timers() # never leave the test run holding one + if not winenv.is_windows(): + check("fine timers: a no-op off Windows", granted is False) + check("fine timers: releasing without holding does not raise", + winenv.release_fine_timers() in (True, False)) + + def test_stop_is_idempotent_and_keeps_the_first_reason(): eng = BeanEngine() eng.start("test", divert=QuietDivert())