Headless Timer epoch uses wall clock (runtime), not simulation_time — first fire under step() is nondeterministic #383

New issue

Closed

opened 2026-07-16 01:08:52 +00:00 by john · 0 comments

john commented

2026-07-16 01:08:52 +00:00

Owner

Summary

In headless mode, a mcrfpy.Timer's first fire under mcrfpy.step() is nondeterministic — it depends on process-startup wall-clock timing, not just the number/size of step() calls. This contradicts the documented headless contract ("timers fire only via step(dt), one event per step") and makes headless timer tests occasionally flaky.

Root cause

There are two clocks:

GameEngine::simulation_time (int ms) — the deterministic headless clock, advanced by step(dt) (GameEngine.cpp:905).
GameEngine::runtime — an sf::Clock, i.e. wall time (GameEngine.h:270).

GameEngine::step() ticks timers against simulation_time:

if (timer && timer->isActive() && timer->hasElapsed(simulation_time)) {
    timer->test(simulation_time);
}

But PyTimer stamps the timer's epoch (last_ran) from the wall clock at creation and at every control method (PyTimer.cpp:80,139,180,195,210,269,310):

current_time = Resources::game->runtime.getElapsedTime().asMilliseconds();

So a timer created at wall-time ≈45 ms has last_ran ≈ 45, but the step loop measures elapsed = simulation_time - last_ran with simulation_time starting near 0. The two clocks are in unrelated reference frames, so how many step() calls occur before the first fire depends on the wall-clock reading at creation — which varies with process load/startup. After the first fire, last_ran is re-stamped and subsequent fires are simulation-driven (hence steady-state behaviour looks deterministic; only the first fire is contaminated).

Reproduction

Surfaced by the #381 snippet-screenshot oracle. Timer-driven snippets 048_timer_control and 191_ui_health_bar_4 produced byte-identical PNGs across 30 isolated runs and most full runs, then flipped once in a full run — a rare first-fire race. Both are Timer-driven with a capture only a few steps in, so the first-fire timing lands right at the capture window.

Fix

Epoch timers from the same clock step() measures them against. A helper:

static int timer_now() {
    if (!Resources::game) return 0;
    return Resources::game->isHeadless()
        ? Resources::game->getSimulationTime()
        : Resources::game->runtime.getElapsedTime().asMilliseconds();
}

replacing the 8 runtime.getElapsedTime().asMilliseconds() reads in PyTimer.cpp. Windowed mode is unchanged; headless becomes fully deterministic (a timer created before any step() gets last_ran = 0, and the first step(0.016) fires a 16 ms timer exactly as expected).

Needs a regression test: create a timer, step() a fixed number of times, assert an exact fire count — reproducibly.

Impact

Blocks the #381 screenshot oracle's reliability (false-positive diffs), and more broadly means existing headless timer tests can flake on first-fire timing. getSimulationTime() (GameEngine.h:334) is already public, so the fix is self-contained.

## Summary In headless mode, a `mcrfpy.Timer`'s first fire under `mcrfpy.step()` is **nondeterministic** — it depends on process-startup wall-clock timing, not just the number/size of `step()` calls. This contradicts the documented headless contract ("timers fire only via `step(dt)`, one event per step") and makes headless timer tests occasionally flaky. ## Root cause There are two clocks: - `GameEngine::simulation_time` (int ms) — the deterministic headless clock, advanced by `step(dt)` (`GameEngine.cpp:905`). - `GameEngine::runtime` — an `sf::Clock`, i.e. **wall time** (`GameEngine.h:270`). `GameEngine::step()` ticks timers against `simulation_time`: ```cpp if (timer && timer->isActive() && timer->hasElapsed(simulation_time)) { timer->test(simulation_time); } ``` But `PyTimer` stamps the timer's epoch (`last_ran`) from the **wall clock** at creation and at every control method (`PyTimer.cpp:80,139,180,195,210,269,310`): ```cpp current_time = Resources::game->runtime.getElapsedTime().asMilliseconds(); ``` So a timer created at wall-time ≈45 ms has `last_ran ≈ 45`, but the step loop measures `elapsed = simulation_time - last_ran` with `simulation_time` starting near 0. The two clocks are in unrelated reference frames, so how many `step()` calls occur before the first fire depends on the wall-clock reading at creation — which varies with process load/startup. After the first fire, `last_ran` is re-stamped and subsequent fires are simulation-driven (hence *steady-state* behaviour looks deterministic; only the **first** fire is contaminated). ## Reproduction Surfaced by the #381 snippet-screenshot oracle. Timer-driven snippets `048_timer_control` and `191_ui_health_bar_4` produced byte-identical PNGs across 30 isolated runs and most full runs, then flipped once in a full run — a rare first-fire race. Both are `Timer`-driven with a capture only a few steps in, so the first-fire timing lands right at the capture window. ## Fix Epoch timers from the same clock `step()` measures them against. A helper: ```cpp static int timer_now() { if (!Resources::game) return 0; return Resources::game->isHeadless() ? Resources::game->getSimulationTime() : Resources::game->runtime.getElapsedTime().asMilliseconds(); } ``` replacing the 8 `runtime.getElapsedTime().asMilliseconds()` reads in `PyTimer.cpp`. Windowed mode is unchanged; headless becomes fully deterministic (a timer created before any `step()` gets `last_ran = 0`, and the first `step(0.016)` fires a 16 ms timer exactly as expected). Needs a regression test: create a timer, `step()` a fixed number of times, assert an exact fire count — reproducibly. ## Impact Blocks the #381 screenshot oracle's reliability (false-positive diffs), and more broadly means existing headless timer tests can flake on first-fire timing. `getSimulationTime()` (`GameEngine.h:334`) is already public, so the fix is self-contained.