diag(motion): A.1 — unthrottled SCFAST/SCFULL + UM_RAW (Commit A.1)
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 <noreply@anthropic.com>
This commit is contained in:
parent
23004a4791
commit
eaa8fc5c67
2 changed files with 45 additions and 38 deletions
|
|
@ -2595,6 +2595,27 @@ public sealed class GameWindow : IDisposable
|
||||||
ushort stance = update.MotionState.Stance;
|
ushort stance = update.MotionState.Stance;
|
||||||
ushort? command = update.MotionState.ForwardCommand;
|
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
|
// Diagnostic: dump every inbound UpdateMotion so we can trace why
|
||||||
// remote chars don't transition off RunForward when they stop.
|
// remote chars don't transition off RunForward when they stop.
|
||||||
// Enable with ACDREAM_DUMP_MOTION=1.
|
// Enable with ACDREAM_DUMP_MOTION=1.
|
||||||
|
|
|
||||||
|
|
@ -283,13 +283,9 @@ public sealed class AnimationSequencer
|
||||||
private const double RateEpsilon = 1e-6;
|
private const double RateEpsilon = 1e-6;
|
||||||
|
|
||||||
// ── Diagnostics (Commit A 2026-05-03) ───────────────────────────────────
|
// ── Diagnostics (Commit A 2026-05-03) ───────────────────────────────────
|
||||||
// Throttle clock for the [SCFAST] / [SCFULL] / [SCNULLFALLBACK] log lines
|
// Removed throttle in A.1 (2026-05-03) — every SCFAST/SCFULL call logs
|
||||||
// emitted from SetCycle. Gated on env var ACDREAM_REMOTE_VEL_DIAG=1; reads
|
// unthrottled (still gated on ACDREAM_REMOTE_VEL_DIAG=1) so we can read
|
||||||
// the env var inline rather than caching so a launch can be re-toggled
|
// exact call rate and Run→Ready transitions one tick at a time.
|
||||||
// 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 ──────────────────────────────────────────────────────────
|
// ── Constructor ──────────────────────────────────────────────────────────
|
||||||
|
|
||||||
|
|
@ -417,22 +413,17 @@ public sealed class AnimationSequencer
|
||||||
}
|
}
|
||||||
|
|
||||||
// D3 (Commit A 2026-05-03): SCFAST — proves whether the fast-path
|
// D3 (Commit A 2026-05-03): SCFAST — proves whether the fast-path
|
||||||
// is firing instead of the full rebuild. If [SCFAST] dominates
|
// is firing instead of the full rebuild.
|
||||||
// during a Walk→Run press AND the leg-cycle hash from D5 doesn't
|
// A.1 (2026-05-03): unthrottled — we need actual call rate, not
|
||||||
// change, H3 (fast-path leaves _currNode on a stale link) is the
|
// 0.5s-bucketed sample. Keeps cost low (just a Console.WriteLine
|
||||||
// bug.
|
// per SetCycle call, all gated on env var).
|
||||||
if (System.Environment.GetEnvironmentVariable("ACDREAM_REMOTE_VEL_DIAG") == "1")
|
if (System.Environment.GetEnvironmentVariable("ACDREAM_REMOTE_VEL_DIAG") == "1")
|
||||||
{
|
{
|
||||||
double nowSec = (System.DateTime.UtcNow - System.DateTime.UnixEpoch).TotalSeconds;
|
System.Console.WriteLine(
|
||||||
if (nowSec - _lastSetCycleDiagTime > 0.5)
|
$"[SCFAST] motion=0x{motion:X8} speedMod={speedMod:F3} "
|
||||||
{
|
+ $"oldSpeedMod={CurrentSpeedMod:F3} "
|
||||||
System.Console.WriteLine(
|
+ $"qCount={_queue.Count} "
|
||||||
$"[SCFAST] motion=0x{motion:X8} speedMod={speedMod:F3} "
|
+ $"currNodeIsCyclic={(_currNode == _firstCyclic)}");
|
||||||
+ $"oldSpeedMod={CurrentSpeedMod:F3} "
|
|
||||||
+ $"qCount={_queue.Count} "
|
|
||||||
+ $"currNodeIsCyclic={(_currNode == _firstCyclic)}");
|
|
||||||
_lastSetCycleDiagTime = nowSec;
|
|
||||||
}
|
|
||||||
}
|
}
|
||||||
return;
|
return;
|
||||||
}
|
}
|
||||||
|
|
@ -555,25 +546,20 @@ public sealed class AnimationSequencer
|
||||||
}
|
}
|
||||||
|
|
||||||
// D3 (Commit A 2026-05-03): SCFULL — counterpart to SCFAST. Fires on
|
// D3 (Commit A 2026-05-03): SCFULL — counterpart to SCFAST. Fires on
|
||||||
// the full-rebuild SetCycle path. Together they tell us the
|
// the full-rebuild SetCycle path.
|
||||||
// fast-path-vs-rebuild ratio. If the visible cycle is wrong despite
|
// A.1 (2026-05-03): unthrottled — see SCFAST comment. We also print
|
||||||
// SCFULL firing with a non-null _currNode and firstNew set, the bug
|
// the previous CurrentMotion so the log directly shows the cycle
|
||||||
// is downstream (H5 PartTemplate divergence, or sequencer-internal
|
// transition (e.g. "Run → Ready" indicates the visible cycle just
|
||||||
// serving stale frames despite correct CurrentMotion).
|
// got reset back to Ready, mid-Run).
|
||||||
if (System.Environment.GetEnvironmentVariable("ACDREAM_REMOTE_VEL_DIAG") == "1")
|
if (System.Environment.GetEnvironmentVariable("ACDREAM_REMOTE_VEL_DIAG") == "1")
|
||||||
{
|
{
|
||||||
double nowSec = (System.DateTime.UtcNow - System.DateTime.UnixEpoch).TotalSeconds;
|
System.Console.WriteLine(
|
||||||
if (nowSec - _lastSetCycleDiagTime > 0.5)
|
$"[SCFULL] prev=0x{CurrentMotion:X8} -> motion=0x{motion:X8} adjustedMotion=0x{adjustedMotion:X8} "
|
||||||
{
|
+ $"speedMod={speedMod:F3} "
|
||||||
System.Console.WriteLine(
|
+ $"qCount={_queue.Count} "
|
||||||
$"[SCFULL] motion=0x{motion:X8} adjustedMotion=0x{adjustedMotion:X8} "
|
+ $"firstNewNull={(firstNew is null)} "
|
||||||
+ $"speedMod={speedMod:F3} "
|
+ $"currNodeIsCyclic={(_currNode == _firstCyclic)} "
|
||||||
+ $"qCount={_queue.Count} "
|
+ $"firstCyclicNull={(_firstCyclic is null)}");
|
||||||
+ $"firstNewNull={(firstNew is null)} "
|
|
||||||
+ $"currNodeIsCyclic={(_currNode == _firstCyclic)} "
|
|
||||||
+ $"firstCyclicNull={(_firstCyclic is null)}");
|
|
||||||
_lastSetCycleDiagTime = nowSec;
|
|
||||||
}
|
|
||||||
}
|
}
|
||||||
|
|
||||||
CurrentStyle = style;
|
CurrentStyle = style;
|
||||||
|
|
|
||||||
Loading…
Add table
Add a link
Reference in a new issue