fix(engine): ask Windows for a fine timer tick while a session runs

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

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

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()

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.
 

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())