diag(motion): instrumentation for remote walk↔run leg-cycle bug (Commit A)

Adds five diagnostics, no behavior changes. All gated on existing
ACDREAM_REMOTE_VEL_DIAG=1 env var. Plan at
~/.claude/plans/yes-make-a-plan-parsed-axolotl.md.

Five hypotheses surviving from the four-agent investigation
(docs/research/2026-05-03-remote-anim-cycle/investigation-prompt.md):

  H1  SEQSTATE silently swallowed by OMEGA_DIAG sharing throttle clock
  H2  ApplyServerControlledVelocityCycle races UM-driven SetCycle per UP
  H3  SetCycle fast-path returns without updating _currNode
  H4  GetLink/GetCycle null → defensive fallback lands on stale head
  H5  PartTemplate.Count diverges from anim PartFrames.Count → silent
       identity-quat freeze

Diagnostics added (all log lines are grep-prefixed):

  D1  Split LastSeqStateLogTime field for SEQSTATE — own throttle.
      Foundational: every other diag depends on SEQSTATE telling truth.
  D2  [UPCYCLE] inside ApplyServerControlledVelocityCycle, +
      [UPCYCLE_SRC] at the call site (wire vs synth velocity).
  D3  [SCFAST] in fast-path return, [SCFULL] at full-rebuild end.
  D4  [SCNULLFALLBACK] in the null-data defensive fallback.
  D5  [PARTSDIAG] with pt.Count / seqFrames.Count / setup.Parts.Count /
       anim.PartFrames[0].Frames.Count + sum-of-components hash.

Repro recipe:

  $env:ACDREAM_INTERP_MANAGER  = "1"
  $env:ACDREAM_REMOTE_VEL_DIAG = "1"
  dotnet run … 2>&1 | Tee-Object tools/diag-logs/walkrun-<ts>.log

Then watch a retail-driven character through acdream and exercise:
idle → W run → release → shift+W walk → release → demote → promote →
run+turn (this last one is the H1 trap).

Decision matrix in the plan file maps each [TAG] signature to a
specific Commit B 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:
Erik 2026-05-03 20:38:47 +02:00
parent 7f1bd1809a
commit 23004a4791
3 changed files with 161 additions and 2 deletions

View file

@ -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 ──────────────────────────────────────────────────────────
/// <summary>
@ -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;