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;