diff --git a/docs/ISSUES.md b/docs/ISSUES.md index 4aa93d64..72f6f3a7 100644 --- a/docs/ISSUES.md +++ b/docs/ISSUES.md @@ -97,14 +97,15 @@ Copy this block when adding a new issue: --- -## #260 — Portal-network wedge: server-round-trip actions die, LOH leaks — REPRODUCED +## #260 — Portal-network wedge: outbound actions die + native/GPU memory climbs -**Status:** OPEN — reproduced live, forensics captured, investigation not started +**Status:** OPEN — investigated 2026-07-29 (two-agent report-only pass over the +captured evidence); fix authorized by the user. **Verdict: two separate roots.** **Severity:** HIGH (renders the client unplayable after sustained portal use) **Filed:** 2026-07-29 (instrumented Coldeve session, Vulkan backend) -**Component:** interaction/use transaction gate + inbound stream + managed memory +**Component:** WorldSession outbound boundary + Vulkan resource lifecycle **Supersedes framing of:** #256 (invisible portal-network objects) and #257 -(~1.5 GB working set) — both are almost certainly facets of this. +(~1.5 GB working set) — both are facets of this. **Reproduction (the first solid one):** on Coldeve (`play.coldeve.ac`), character Barris, after several portal-network runs returning to the town portal network, @@ -116,36 +117,41 @@ gcdump taken *in the broken state* (15 MB), full session log with `[cell-transit]`/`[input]`/`[use-target]`/`equipment` traces, the `dotnet-counters` CSV, and stderr. -**Two symptoms, established from the traces:** -1. **The outbound action pipeline is wedged.** `CombatToggleCombat Press` × 3 - produced **zero outbound send** (movement, being client-predicted, still - produces `[cell-transit]`). Signature of the one-request-at-a-time - interaction/use gate (J5.2) latching closed because a `UseWithTarget` never - received its server ack — a burst of `[use-target] … SEND UseWithTarget` - precedes the hang. Every server-round-trip action (portal use, combat mode) - is then silently dropped; local-only actions still work. -2. **A managed leak on the LOH — this one is ours.** `dotnet-counters` at wedge: - **LOH 601,807,472 B (574 MB)**, process WS 3.2 GB — distinct from the flat - ~1.9 GB residency *level* the V11 soak plateaued at (that was benign; this - climbs under live walked play). Fingerprint matches the project's prior LOH - leak class (per-event `float[]`/`byte[]` never released). 185 `equipment: - attached … RightHandCombat` re-attach lines but only 1 CreateObject, so it is - re-attach/replay churn on existing entities, not fresh-object accumulation. +**Root 1 — the wedge (cause still open, field narrowed).** The as-filed +hypothesis (J5.2 use gate latched by an un-acked `UseWithTarget`) is **refuted**: +the log shows every `UseWithTarget` received its matching `[use-done]`, all +reveal generations 2→17 reached `event=complete cancelled=False failures=0`, +and `RuntimeCombatModeState.Toggle()` +(`src/AcDream.Runtime/Gameplay/RuntimeCombatModeState.cs:49-93`) never touches +that gate — it gates only on `IsInWorld`. Remaining ranked hypotheses: +(1) frame-thread saturation — inbound drains from an *unbounded* +`_inboundQueue` on a ~4 ms frame budget (`WorldSession.cs:990-1016`), collapsed +by Root 2's memory pressure; (2) outbound ISAAC/sequence desync — a send off +the frame thread desyncs the cipher (`NextGameActionSequence()` is a non-atomic +`++`, `WorldSession.cs:1618`) and the server silently drops every subsequent +packet, which uniquely explains hard-zero effect while client-predicted +movement survives. -**Hypothesis (unproven, for the investigation):** a jammed inbound stream could -both starve the ack the use-gate waits on AND accumulate LOH buffers — one root, -two symptoms. Or two bugs. The gcdump names the LOH type by retainer; the log -timeline names the unacked request. Not confirmed either way. +**Root 2 — the memory climb is NATIVE/GPU, not managed.** The as-filed "LOH +leak" is wrong: LOH is a bounded sawtooth (318→829→318 MiB; churn, not +retention) and live managed heap at wedge was only 333 MB. The monotonic climb +is **working set 1,295→3,261 MiB (~180 MB/min)**; at peak, WS 3,261 vs managed +committed 1,015 MiB leaves **~2.25 GB unaccounted native/GPU memory**. Prime +suspect: Vulkan device resources minted per equipment re-attach (185–187 +`equipment: attached … RightHandCombat` lines vs 1 CreateObject) and per vfx +setup, never released. **Why the scripted gates missed it:** the V11 portal-churn soak used `/teleloc`, which enters the transit state machine by a different door than a *walked* portal transit — exactly the gap the walked-play session was designed to probe. -**Next (investigation, user-approved fix only):** read the gcdump retainer graph -per `reference_memory_leak_toolchain.md`; reconstruct the use-gate timeline from -the log to find the unacked request; determine shared-vs-separate root. Do NOT -patch the symptom (a gate timeout would be the classic forbidden workaround) — -find why the ack never lands. +**Next (authorized):** (a) instrument the `WorldSession` outbound boundary — +opcode+sequence per send, swallowed exceptions, `IsInWorld`, per-frame dt, +inbound-queue depth — and reproduce with walked portal play; at a dead combat +toggle, whether the send reaches the wire and whether the sequence still +advances distinguishes the remaining hypotheses. (b) audit the +attach→GPU-resource path for create-without-release. Do NOT patch the symptom +(a gate timeout or retry loop is the classic forbidden workaround). --- diff --git a/src/AcDream.App/Runtime/CurrentGameRuntimeCommandAdapter.cs b/src/AcDream.App/Runtime/CurrentGameRuntimeCommandAdapter.cs index 64eb0cdc..b4d19237 100644 --- a/src/AcDream.App/Runtime/CurrentGameRuntimeCommandAdapter.cs +++ b/src/AcDream.App/Runtime/CurrentGameRuntimeCommandAdapter.cs @@ -231,6 +231,17 @@ internal sealed class CurrentGameRuntimeCommandAdapter RuntimeCommandStatus.Inactive, _ => RuntimeCommandStatus.Rejected, }; + // #260 probe: the toggle's own Inactive exit comes from a + // DIFFERENT IsInWorld source than Validate's (the operations + // slot, which reads false when unbound). Logging the result + // here separates "gate passed, toggle refused" from "gate + // rejected" — the two look identical to the player. + if (AcDream.Core.Net.NetDiagnostics.ProbeNet) + { + Console.WriteLine( + $"[cmd-gate] combat toggle result={result.Status}" + + $" mode={result.Mode}"); + } } else { @@ -753,13 +764,31 @@ internal sealed class CurrentGameRuntimeCommandAdapter RuntimeGenerationToken expectedGeneration, bool requireWorld) { + RuntimeCommandStatus status; if (_view.Lifecycle.State == RuntimeLifecycleState.Disposed) - return RuntimeCommandStatus.Inactive; - if (expectedGeneration != _view.Generation) - return RuntimeCommandStatus.StaleGeneration; - if (requireWorld && !_session.IsInWorld) - return RuntimeCommandStatus.Inactive; - return RuntimeCommandStatus.Accepted; + status = RuntimeCommandStatus.Inactive; + else if (expectedGeneration != _view.Generation) + status = RuntimeCommandStatus.StaleGeneration; + else if (requireWorld && !_session.IsInWorld) + status = RuntimeCommandStatus.Inactive; + else + status = RuntimeCommandStatus.Accepted; + + // #260 probe: a rejected generation-gated command is otherwise + // COMPLETELY silent (no log, no event) — which is exactly how the + // portal-network wedge hid. Log every rejection with the full gate + // state so the failing predicate names itself. + if (status != RuntimeCommandStatus.Accepted + && AcDream.Core.Net.NetDiagnostics.ProbeNet) + { + Console.WriteLine( + $"[cmd-gate] REJECT status={status}" + + $" expected={expectedGeneration}" + + $" view={_view.Generation}" + + $" lifecycle={_view.Lifecycle.State}" + + $" inWorld={_session.IsInWorld}"); + } + return status; } private RuntimeCommandResult Result( diff --git a/src/AcDream.Core.Net/NetDiagnostics.cs b/src/AcDream.Core.Net/NetDiagnostics.cs new file mode 100644 index 00000000..7ac800e3 --- /dev/null +++ b/src/AcDream.Core.Net/NetDiagnostics.cs @@ -0,0 +1,36 @@ +namespace AcDream.Core.Net; + +/// +/// Diagnostic owner for the ACDREAM_PROBE_NET probe family (#260). +/// Read once at startup, following the PhysicsDiagnostics pattern. +/// +/// +/// When enabled, three probe line families are emitted: +/// +/// [net-out] — one line per outbound reliable game message at the +/// WorldSession.SendGameMessage chokepoint: opcode, game-action type + +/// sequence (when the body is a 0xF7B1 GameAction), fragment/packet sequence, +/// managed thread id, and session state. An exception escaping the wire write +/// additionally emits [net-out-EX] via an exception filter (log +/// without catching — behavior is unchanged). +/// [net-tick] — a once-per-second cadence summary from +/// WorldSession.Tick: inbound datagrams/s, remaining queue depth, +/// budget-break count, worst inter-tick gap (= worst frame stall as seen by +/// the net pump), outbound sends/s, and acks/s. +/// [cmd-gate] — one line per generation-gated runtime command +/// REJECTION in CurrentGameRuntimeCommandAdapter.Validate (status, +/// expected vs view generation, lifecycle, IsInWorld) plus the combat-toggle +/// result. These rejections are otherwise completely silent, which is what +/// let #260's wedge hide. +/// +/// Zero steady-state cost when off: every site is behind this single bool. +/// +/// +public static class NetDiagnostics +{ + /// + /// ACDREAM_PROBE_NET=1 — #260 outbound/command-gate probe family. + /// + public static bool ProbeNet { get; set; } = + Environment.GetEnvironmentVariable("ACDREAM_PROBE_NET") == "1"; +} diff --git a/src/AcDream.Core.Net/WorldSession.cs b/src/AcDream.Core.Net/WorldSession.cs index 38602a84..f3109efd 100644 --- a/src/AcDream.Core.Net/WorldSession.cs +++ b/src/AcDream.Core.Net/WorldSession.cs @@ -990,6 +990,7 @@ public sealed class WorldSession : IDisposable public int Tick() { int processed = 0; + bool budgetBroke = false; long start = Stopwatch.GetTimestamp(); while (_inboundQueue.Reader.TryRead( out PooledInboundDatagram datagram)) @@ -1010,11 +1011,74 @@ public sealed class WorldSession : IDisposable // tolerance (holtburger defers acks on a flush cadence). The tail stays queued // (unbounded channel, FIFO) and drains next frame. if (InboundBudgetExceeded(CurrentState, start, Stopwatch.GetTimestamp(), InboundBudgetTicks)) + { + budgetBroke = true; break; + } } + if (NetDiagnostics.ProbeNet) + ProbeNetTickCadence(start, processed, budgetBroke); return processed; } + // #260 probe state — only touched when NetDiagnostics.ProbeNet is set. + // The inter-Tick gap doubles as a frame-stall witness: Tick runs once per + // frame on the frame thread, so a GC pause or saturated frame shows up + // directly as maxgap. _probeSendWindow/_probeAckWindow are Interlocked so + // a hypothetical off-thread send can't corrupt the window counters (the + // [net-out] tid field is what would prove such a send exists). + private long _probeLastTickTs; + private long _probeWindowStartTs; + private long _probeMaxGapTicks; + private int _probeProcessedWindow; + private int _probeBudgetBreaks; + private int _probeSendWindow; + private int _probeAckWindow; + + /// + /// #260 probe: accumulate per-Tick cadence facts and emit one + /// [net-tick] summary line per second. + /// + private void ProbeNetTickCadence(long tickStartTs, int processed, bool budgetBroke) + { + if (_probeLastTickTs != 0) + { + long gap = tickStartTs - _probeLastTickTs; + if (gap > _probeMaxGapTicks) + _probeMaxGapTicks = gap; + } + _probeLastTickTs = tickStartTs; + _probeProcessedWindow += processed; + if (budgetBroke) + _probeBudgetBreaks++; + + if (_probeWindowStartTs == 0) + { + _probeWindowStartTs = tickStartTs; + return; + } + long windowTicks = tickStartTs - _probeWindowStartTs; + if (windowTicks < Stopwatch.Frequency) + return; + + double windowSeconds = (double)windowTicks / Stopwatch.Frequency; + double maxGapMs = _probeMaxGapTicks * 1000.0 / Stopwatch.Frequency; + int sends = Interlocked.Exchange(ref _probeSendWindow, 0); + int acks = Interlocked.Exchange(ref _probeAckWindow, 0); + Console.WriteLine( + $"[net-tick] in/s={_probeProcessedWindow / windowSeconds:F0}" + + $" q={_inboundQueue.Reader.Count}" + + $" budget-breaks={_probeBudgetBreaks}" + + $" maxgap={maxGapMs:F0}ms" + + $" out/s={sends / windowSeconds:F0}" + + $" acks/s={acks / windowSeconds:F0}" + + $" st={CurrentState}"); + _probeWindowStartTs = tickStartTs; + _probeMaxGapTicks = 0; + _probeProcessedWindow = 0; + _probeBudgetBreaks = 0; + } + /// /// Pure, testable decision for the per-frame inbound bound: stop draining only when /// in-world AND the elapsed Stopwatch ticks have reached the budget. Extracted so the @@ -2162,28 +2226,81 @@ public sealed class WorldSession : IDisposable private void SendGameMessage(byte[] gameMessageBody, GameMessageGroup queue) { - Span datagram = stackalloc byte[ - PacketHeader.Size - + MessageFragmentHeader.MaxFragmentSize]; - int fragmentLength = - GameMessageFragment.WriteSingleFragment( - datagram.Slice(PacketHeader.Size), - _fragmentSequence++, - queue, - gameMessageBody); - var header = new PacketHeader + // #260 probe: log the send BEFORE the sequence counters are consumed + // so the line carries the values this datagram will actually use. The + // exception filter below logs a wire-write fault WITHOUT catching it + // (the filter returns false), so behavior is byte-identical either way. + if (NetDiagnostics.ProbeNet) + ProbeNetLogOutbound(gameMessageBody, queue); + try { - Sequence = _clientPacketSequence++, - Flags = PacketHeaderFlags.BlobFragments | PacketHeaderFlags.EncryptedChecksum, - Id = _sessionClientId, - }; - int datagramLength = PacketCodec.FinalizeInPlace( - header, - datagram, - fragmentLength, - optionalLength: 0, - _outboundIsaac); - _net.Send(datagram.Slice(0, datagramLength)); + Span datagram = stackalloc byte[ + PacketHeader.Size + + MessageFragmentHeader.MaxFragmentSize]; + int fragmentLength = + GameMessageFragment.WriteSingleFragment( + datagram.Slice(PacketHeader.Size), + _fragmentSequence++, + queue, + gameMessageBody); + var header = new PacketHeader + { + Sequence = _clientPacketSequence++, + Flags = PacketHeaderFlags.BlobFragments | PacketHeaderFlags.EncryptedChecksum, + Id = _sessionClientId, + }; + int datagramLength = PacketCodec.FinalizeInPlace( + header, + datagram, + fragmentLength, + optionalLength: 0, + _outboundIsaac); + _net.Send(datagram.Slice(0, datagramLength)); + } + catch (Exception ex) when (ProbeNetLogOutboundFault(ex)) + { + // Unreachable: the filter always returns false so the original + // exception propagates to the caller exactly as before. + throw; + } + if (NetDiagnostics.ProbeNet) + Interlocked.Increment(ref _probeSendWindow); + } + + /// + /// #260 probe: one [net-out] line per outbound reliable game + /// message. The thread id is load-bearing evidence — every send is + /// supposed to happen on the frame thread (the ISAAC keystream is + /// single-threaded); two distinct tids across [net-out] lines would + /// prove the cross-thread-send/cipher-desync hypothesis by itself. + /// + private void ProbeNetLogOutbound(byte[] body, GameMessageGroup queue) + { + uint op = body.Length >= 4 + ? BinaryPrimitives.ReadUInt32LittleEndian(body) + : 0u; + string detail = string.Empty; + if (op == 0xF7B1 && body.Length >= 12) + { + uint gseq = BinaryPrimitives.ReadUInt32LittleEndian(body.AsSpan(4)); + uint act = BinaryPrimitives.ReadUInt32LittleEndian(body.AsSpan(8)); + detail = $" act=0x{act:X4} gseq={gseq}"; + } + Console.WriteLine( + $"[net-out] op=0x{op:X4}{detail} q={queue} fseq={_fragmentSequence}" + + $" pseq={_clientPacketSequence} len={body.Length}" + + $" tid={Environment.CurrentManagedThreadId} st={CurrentState}"); + } + + private bool ProbeNetLogOutboundFault(Exception ex) + { + if (NetDiagnostics.ProbeNet) + { + Console.WriteLine( + $"[net-out-EX] {ex.GetType().Name}: {ex.Message}" + + $" tid={Environment.CurrentManagedThreadId} st={CurrentState}"); + } + return false; } /// @@ -2239,6 +2356,8 @@ public sealed class WorldSession : IDisposable optionalLength: sizeof(uint), outboundIsaac: null); _net.Send(datagram.Slice(0, datagramLength)); + if (NetDiagnostics.ProbeNet) + Interlocked.Increment(ref _probeAckWindow); } private void Transition(State next)