diff --git a/src/AcDream.App/Rendering/GameWindow.cs b/src/AcDream.App/Rendering/GameWindow.cs index 8c7bc94..b19a973 100644 --- a/src/AcDream.App/Rendering/GameWindow.cs +++ b/src/AcDream.App/Rendering/GameWindow.cs @@ -377,6 +377,23 @@ public sealed class GameWindow : IDisposable public double PrevServerPosTime; public double LastOmegaDiagLogTime; /// + /// Diagnostic-only (gated on ACDREAM_REMOTE_VEL_DIAG=1): own + /// throttle clock for the SEQSTATE log line in TickAnimations. + /// Previously SEQSTATE shared with + /// the OMEGA_DIAG block, which fires at 0.5s and resets the clock — + /// any remote that turned during a transition silently swallowed + /// SEQSTATE for 0.5–1.5s, masking the bug we're trying to diagnose + /// (walk↔run leg-cycle sticking on observed retail chars). Split + /// 2026-05-03 (Commit A). + /// + public double LastSeqStateLogTime; + /// + /// Diagnostic-only (gated on ACDREAM_REMOTE_VEL_DIAG=1): own + /// throttle clock for the PARTSDIAG log line in TickAnimations + /// (D5). One log per remote per ~1s. + /// + public double LastPartsDiagLogTime; + /// /// Diagnostic-only: max |sequencer.CurrentVelocity| observed across /// all per-tick samples since the last UpdatePosition arrival. The /// next UP compares this against (LastServerPos - PrevServerPos) / @@ -3295,6 +3312,23 @@ public sealed class GameWindow : IDisposable uint style = ae.Sequencer.CurrentStyle != 0 ? ae.Sequencer.CurrentStyle : 0x8000003Du; + + // D2 (Commit A 2026-05-03): UPCYCLE diag — proves whether + // ApplyServerControlledVelocityCycle is racing UpdateMotion-driven + // SetCycle for player-driven remotes. If this fires every ~100-200ms + // during a Walk→Run press with `motion` flipping between buckets, + // H2 (UP-vs-UM race) is confirmed. UPs (5-10 Hz) would then + // perpetually overwrite the cycle the UM just set. + if (System.Environment.GetEnvironmentVariable("ACDREAM_REMOTE_VEL_DIAG") == "1") + { + System.Console.WriteLine( + $"[UPCYCLE] guid={serverGuid:X8} " + + $"vel=({velocity.X:F2},{velocity.Y:F2},{velocity.Z:F2}) " + + $"|v|={velocity.Length():F2} " + + $"-> motion=0x{plan.Motion:X8} speedMod={plan.SpeedMod:F2} " + + $"prev=0x{currentMotion:X8} " + + $"airborne={rm.Airborne} moveTo={rm.ServerMoveToActive}"); + } ae.Sequencer.SetCycle(style, plan.Motion, plan.SpeedMod); } @@ -3607,6 +3641,17 @@ public sealed class GameWindow : IDisposable && rmState.HasServerVelocity && _animatedEntities.TryGetValue(entity.Id, out var aeForVelocity)) { + // D2 (Commit A 2026-05-03): tag whether the velocity feeding + // ApplyServerControlledVelocityCycle is wire-explicit (rare for + // player remotes — ACE almost never sets HasVelocity on player + // UPs) or synthesized from position deltas (the common case). + // Pairs with the [UPCYCLE] line printed inside the call. + if (System.Environment.GetEnvironmentVariable("ACDREAM_REMOTE_VEL_DIAG") == "1") + { + string velSrc = update.Velocity is null ? "synth" : "wire"; + System.Console.WriteLine( + $"[UPCYCLE_SRC] guid={update.Guid:X8} src={velSrc}"); + } ApplyServerControlledVelocityCycle( update.Guid, aeForVelocity, @@ -6522,12 +6567,16 @@ public sealed class GameWindow : IDisposable { double nowSec = (System.DateTime.UtcNow - System.DateTime.UnixEpoch).TotalSeconds; if (_remoteDeadReckon.TryGetValue(serverGuid, out var rmDiag) - && nowSec - rmDiag.LastOmegaDiagLogTime > 1.0) + && nowSec - rmDiag.LastSeqStateLogTime > 1.0) { + // D1 (2026-05-03): SEQSTATE has its own throttle clock + // (LastSeqStateLogTime) so it isn't silently swallowed by + // OMEGA_DIAG resetting LastOmegaDiagLogTime when the + // observed remote happens to be turning. System.Console.WriteLine( $"[SEQSTATE] guid={serverGuid:X8} CurrentMotion=0x{ae.Sequencer.CurrentMotion:X8} " + $"CurrentSpeedMod={ae.Sequencer.CurrentSpeedMod:F3}"); - rmDiag.LastOmegaDiagLogTime = nowSec; + rmDiag.LastSeqStateLogTime = nowSec; } } seqFrames = ae.Sequencer.Advance(dt); @@ -6564,6 +6613,51 @@ public sealed class GameWindow : IDisposable } int partCount = ae.PartTemplate.Count; + + // D5 (Commit A 2026-05-03): PARTSDIAG — proves whether + // PartTemplate.Count diverges from seqFrames.Count (silent + // identity-quat fallback freezes parts → H5) and whether the + // per-part frames returned by Advance actually change between + // Walk and Run cycles. The seqFrames hash is a sum-of-components + // proxy: cheap, unitless, monotonically distinct between cycles + // for any non-degenerate animation. If [PARTSDIAG] shows the + // hash unchanged across a Walk→Run transition while [SEQSTATE] + // shows CurrentMotion flipping, the sequencer is serving stale + // frames despite the cycle being correct. + if (System.Environment.GetEnvironmentVariable("ACDREAM_REMOTE_VEL_DIAG") == "1" + && serverGuid != 0 + && serverGuid != _playerServerGuid + && _remoteDeadReckon.TryGetValue(serverGuid, out var rmParts)) + { + double nowSecParts = (System.DateTime.UtcNow - System.DateTime.UnixEpoch).TotalSeconds; + if (nowSecParts - rmParts.LastPartsDiagLogTime > 1.0) + { + int seqCount = seqFrames?.Count ?? -1; + int setupParts = ae.Setup.Parts.Count; + int animFrame0Parts = ae.Animation.PartFrames.Count > 0 + ? ae.Animation.PartFrames[0].Frames.Count + : -1; + double seqHash = 0.0; + if (seqFrames is not null) + { + for (int hi = 0; hi < seqFrames.Count; hi++) + { + var f = seqFrames[hi]; + seqHash += f.Origin.X + f.Origin.Y + f.Origin.Z + + f.Orientation.X + f.Orientation.Y + + f.Orientation.Z + f.Orientation.W; + } + } + System.Console.WriteLine( + $"[PARTSDIAG] guid={serverGuid:X8} " + + $"pt.Count={partCount} seqFrames.Count={seqCount} " + + $"setup.Parts.Count={setupParts} " + + $"anim.PartFrames[0].Frames.Count={animFrame0Parts} " + + $"seqHash={seqHash:F4}"); + rmParts.LastPartsDiagLogTime = nowSecParts; + } + } + var newMeshRefs = new List(partCount); var scaleMat = ae.Scale == 1.0f ? System.Numerics.Matrix4x4.Identity diff --git a/src/AcDream.Core/Physics/AnimationSequencer.cs b/src/AcDream.Core/Physics/AnimationSequencer.cs index 7fc7e68..bbdd66f 100644 --- a/src/AcDream.Core/Physics/AnimationSequencer.cs +++ b/src/AcDream.Core/Physics/AnimationSequencer.cs @@ -282,6 +282,15 @@ public sealed class AnimationSequencer private const double FrameEpsilon = 1e-5; 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; + // ── Constructor ────────────────────────────────────────────────────────── /// @@ -406,6 +415,25 @@ public sealed class AnimationSequencer MultiplyCyclicFramerate(speedMod / CurrentSpeedMod); CurrentSpeedMod = speedMod; } + + // 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. + 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; + } + } return; } @@ -510,6 +538,42 @@ public sealed class AnimationSequencer // Defensive fallback: nothing newly added AND no current node. _currNode = _queue.First; _framePosition = _currNode?.Value.GetStartFramePosition() ?? 0.0; + + // D4 (Commit A 2026-05-03): SCNULLFALLBACK — proves whether the + // null-data fallback is being hit. If this fires during a + // Walk→Run transition for the watched remote, H4 (MotionTable + // GetLink/GetCycle returns null for the remote's setup) is the + // bug. linkData/cycleData null almost certainly means a + // MotionTable lookup gap for that style+motion combo. + if (System.Environment.GetEnvironmentVariable("ACDREAM_REMOTE_VEL_DIAG") == "1") + { + System.Console.WriteLine( + $"[SCNULLFALLBACK] motion=0x{motion:X8} adjustedMotion=0x{adjustedMotion:X8} " + + $"linkNull={(linkData is null)} cycleNull={(cycleData is null)} " + + $"qCount={_queue.Count}"); + } + } + + // 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). + 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; + } } CurrentStyle = style; diff --git a/tools/diag-logs/.gitignore b/tools/diag-logs/.gitignore new file mode 100644 index 0000000..397b4a7 --- /dev/null +++ b/tools/diag-logs/.gitignore @@ -0,0 +1 @@ +*.log