From eaa8fc5c6728ed68d8474293613e6ded82b81265 Mon Sep 17 00:00:00 2001 From: Erik Date: Sun, 3 May 2026 20:51:14 +0200 Subject: [PATCH] =?UTF-8?q?diag(motion):=20A.1=20=E2=80=94=20unthrottled?= =?UTF-8?q?=20SCFAST/SCFULL=20+=20UM=5FRAW=20(Commit=20A.1)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Commit A's log refuted H2 (UPCYCLE never fires for player guids β€” gated by IsPlayerGuid), H4 (SCNULLFALLBACK count = 0), H5 (PartTemplate counts always match anim PartFrames). The remaining puzzle: SCFULL Ready=23 dominates (all motions: 41 total) SETCYCLE picker logged: only 9 transitions to Ready Difference (β‰₯14 extra Ready full-rebuilds) suggests a non-picker source, OR many UMs arriving with no ForwardCommand bit being routed through the picker's `else if (!command.HasValue) { fullMotion = Ready; }` at GameWindow.cs:2671-2673, knocking the cycle back to Ready mid-Walk/Run. This commit removes the 0.5s throttle on SCFAST and SCFULL (every call now logs) and adds [UM_RAW] at OnLiveMotionUpdated entry to print: - stance / fwd / fwdSpd / side / turn / movementType / isMoveTo - sequencer.CurrentMotion at call time per UM, gated on ACDREAM_REMOTE_VEL_DIAG=1. Combined: one repro pass tells us (a) UM arrival rate per remote, (b) which UMs lack ForwardCommand, (c) whether the picker is the source of the 14+ extra Ready calls. Commit B is then a one-line fix. πŸ€– Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude Opus 4.7 --- src/AcDream.App/Rendering/GameWindow.cs | 21 +++++++ .../Physics/AnimationSequencer.cs | 62 +++++++------------ 2 files changed, 45 insertions(+), 38 deletions(-) diff --git a/src/AcDream.App/Rendering/GameWindow.cs b/src/AcDream.App/Rendering/GameWindow.cs index b19a973..655aee7 100644 --- a/src/AcDream.App/Rendering/GameWindow.cs +++ b/src/AcDream.App/Rendering/GameWindow.cs @@ -2595,6 +2595,27 @@ public sealed class GameWindow : IDisposable ushort stance = update.MotionState.Stance; ushort? command = update.MotionState.ForwardCommand; + // A.1 (Commit A.1 2026-05-03): UM_RAW β€” every inbound UM, one line, + // gated on ACDREAM_REMOTE_VEL_DIAG=1. Skips the local player. Tells + // us the actual UM arrival rate per remote and which fields are set + // on each. The bug-suspect is "ACE sends UMs without ForwardCommand + // bit during running, our picker resolves to Ready, SetCycle(Ready) + // resets the cycle". This diag lets us count how often that happens. + if (System.Environment.GetEnvironmentVariable("ACDREAM_REMOTE_VEL_DIAG") == "1" + && update.Guid != _playerServerGuid) + { + string cmdStrRaw = command.HasValue ? $"0x{command.Value:X4}" : "null"; + string sideStr = update.MotionState.SideStepCommand is { } s ? $"0x{s:X4}" : "null"; + string turnStr = update.MotionState.TurnCommand is { } t ? $"0x{t:X4}" : "null"; + string fwdSpdStr = update.MotionState.ForwardSpeed is { } fs ? $"{fs:F2}" : "null"; + uint seqMot = ae.Sequencer?.CurrentMotion ?? 0; + System.Console.WriteLine( + $"[UM_RAW] guid={update.Guid:X8} stance=0x{stance:X4} fwd={cmdStrRaw} fwdSpd={fwdSpdStr} " + + $"side={sideStr} turn={turnStr} mt=0x{update.MotionState.MovementType:X2} " + + $"isMoveTo={update.MotionState.IsServerControlledMoveTo} " + + $"seq.CurrentMotion=0x{seqMot:X8}"); + } + // Diagnostic: dump every inbound UpdateMotion so we can trace why // remote chars don't transition off RunForward when they stop. // Enable with ACDREAM_DUMP_MOTION=1. diff --git a/src/AcDream.Core/Physics/AnimationSequencer.cs b/src/AcDream.Core/Physics/AnimationSequencer.cs index bbdd66f..fa7b23d 100644 --- a/src/AcDream.Core/Physics/AnimationSequencer.cs +++ b/src/AcDream.Core/Physics/AnimationSequencer.cs @@ -283,13 +283,9 @@ public sealed class AnimationSequencer private const double RateEpsilon = 1e-6; // ── Diagnostics (Commit A 2026-05-03) ─────────────────────────────────── - // Throttle clock for the [SCFAST] / [SCFULL] / [SCNULLFALLBACK] log lines - // emitted from SetCycle. Gated on env var ACDREAM_REMOTE_VEL_DIAG=1; reads - // the env var inline rather than caching so a launch can be re-toggled - // without restarting. Throttled to one log per ~0.5s per sequencer - // instance; the log line itself carries the motion ID so multiple cycles - // alternating fast still get distinguished in the log. - private double _lastSetCycleDiagTime; + // Removed throttle in A.1 (2026-05-03) β€” every SCFAST/SCFULL call logs + // unthrottled (still gated on ACDREAM_REMOTE_VEL_DIAG=1) so we can read + // exact call rate and Runβ†’Ready transitions one tick at a time. // ── Constructor ────────────────────────────────────────────────────────── @@ -417,22 +413,17 @@ public sealed class AnimationSequencer } // D3 (Commit A 2026-05-03): SCFAST β€” proves whether the fast-path - // is firing instead of the full rebuild. If [SCFAST] dominates - // during a Walkβ†’Run press AND the leg-cycle hash from D5 doesn't - // change, H3 (fast-path leaves _currNode on a stale link) is the - // bug. + // is firing instead of the full rebuild. + // A.1 (2026-05-03): unthrottled β€” we need actual call rate, not + // 0.5s-bucketed sample. Keeps cost low (just a Console.WriteLine + // per SetCycle call, all gated on env var). if (System.Environment.GetEnvironmentVariable("ACDREAM_REMOTE_VEL_DIAG") == "1") { - double nowSec = (System.DateTime.UtcNow - System.DateTime.UnixEpoch).TotalSeconds; - if (nowSec - _lastSetCycleDiagTime > 0.5) - { - System.Console.WriteLine( - $"[SCFAST] motion=0x{motion:X8} speedMod={speedMod:F3} " - + $"oldSpeedMod={CurrentSpeedMod:F3} " - + $"qCount={_queue.Count} " - + $"currNodeIsCyclic={(_currNode == _firstCyclic)}"); - _lastSetCycleDiagTime = nowSec; - } + System.Console.WriteLine( + $"[SCFAST] motion=0x{motion:X8} speedMod={speedMod:F3} " + + $"oldSpeedMod={CurrentSpeedMod:F3} " + + $"qCount={_queue.Count} " + + $"currNodeIsCyclic={(_currNode == _firstCyclic)}"); } return; } @@ -555,25 +546,20 @@ public sealed class AnimationSequencer } // D3 (Commit A 2026-05-03): SCFULL β€” counterpart to SCFAST. Fires on - // the full-rebuild SetCycle path. Together they tell us the - // fast-path-vs-rebuild ratio. If the visible cycle is wrong despite - // SCFULL firing with a non-null _currNode and firstNew set, the bug - // is downstream (H5 PartTemplate divergence, or sequencer-internal - // serving stale frames despite correct CurrentMotion). + // the full-rebuild SetCycle path. + // A.1 (2026-05-03): unthrottled β€” see SCFAST comment. We also print + // the previous CurrentMotion so the log directly shows the cycle + // transition (e.g. "Run β†’ Ready" indicates the visible cycle just + // got reset back to Ready, mid-Run). if (System.Environment.GetEnvironmentVariable("ACDREAM_REMOTE_VEL_DIAG") == "1") { - double nowSec = (System.DateTime.UtcNow - System.DateTime.UnixEpoch).TotalSeconds; - if (nowSec - _lastSetCycleDiagTime > 0.5) - { - System.Console.WriteLine( - $"[SCFULL] motion=0x{motion:X8} adjustedMotion=0x{adjustedMotion:X8} " - + $"speedMod={speedMod:F3} " - + $"qCount={_queue.Count} " - + $"firstNewNull={(firstNew is null)} " - + $"currNodeIsCyclic={(_currNode == _firstCyclic)} " - + $"firstCyclicNull={(_firstCyclic is null)}"); - _lastSetCycleDiagTime = nowSec; - } + System.Console.WriteLine( + $"[SCFULL] prev=0x{CurrentMotion:X8} -> motion=0x{motion:X8} adjustedMotion=0x{adjustedMotion:X8} " + + $"speedMod={speedMod:F3} " + + $"qCount={_queue.Count} " + + $"firstNewNull={(firstNew is null)} " + + $"currNodeIsCyclic={(_currNode == _firstCyclic)} " + + $"firstCyclicNull={(_firstCyclic is null)}"); } CurrentStyle = style;