diag(net): #260 outbound/command-gate probe + corrected issue framing
The two-agent investigation refuted #260's as-filed hypotheses: every UseWithTarget was acked (the J5.2 use gate never latched), and the LOH leak is bounded sawtooth churn - the real climb is ~2.25 GB of native/ GPU memory (WS 3,261 vs managed 1,015 MiB at wedge). The wedge evidence also showed why it could hide: the live combat toggle routes through the generation-gated runtime command seam, and every rejection exit in that chain (Disposed / StaleGeneration / !IsInWorld at Validate, plus the operations slot reading IsInWorld=false when unbound) is COMPLETELY silent - no log, no event. ACDREAM_PROBE_NET=1 (NetDiagnostics owner, PhysicsDiagnostics pattern) now arms three probe families, all zero-cost when off: - [net-out] per reliable send at the SendGameMessage chokepoint: opcode, GameAction type+sequence, fragment/packet sequence, managed thread id (two tids would prove the cross-thread ISAAC-desync hypothesis alone), and state; [net-out-EX] via an exception FILTER that logs without catching, so propagation is unchanged. - [net-tick] 1 Hz cadence from WorldSession.Tick: inbound/s, queue depth, budget breaks, worst inter-tick gap (frame-stall witness), out/s, acks/s. - [cmd-gate] every silent runtime-command rejection with expected-vs- view generation, lifecycle, and IsInWorld, plus the combat toggle result (whose Inactive exit reads a DIFFERENT IsInWorld source). One walked-portal repro session with this probe distinguishes all remaining #260 wedge hypotheses. ISSUES.md #260 rewritten to the corrected two-root framing. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Erik
parent
ab3da28c34
commit
534bacbc23
4 changed files with 245 additions and 55 deletions
|
|
@ -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).
|
||||
|
||||
---
|
||||
|
||||
|
|
|
|||
|
|
@ -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(
|
||||
|
|
|
|||
36
src/AcDream.Core.Net/NetDiagnostics.cs
Normal file
36
src/AcDream.Core.Net/NetDiagnostics.cs
Normal file
|
|
@ -0,0 +1,36 @@
|
|||
namespace AcDream.Core.Net;
|
||||
|
||||
/// <summary>
|
||||
/// Diagnostic owner for the <c>ACDREAM_PROBE_NET</c> probe family (#260).
|
||||
/// Read once at startup, following the <c>PhysicsDiagnostics</c> pattern.
|
||||
///
|
||||
/// <para>
|
||||
/// When enabled, three probe line families are emitted:
|
||||
/// <list type="bullet">
|
||||
/// <item><c>[net-out]</c> — one line per outbound reliable game message at the
|
||||
/// <c>WorldSession.SendGameMessage</c> 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 <c>[net-out-EX]</c> via an exception filter (log
|
||||
/// without catching — behavior is unchanged).</item>
|
||||
/// <item><c>[net-tick]</c> — a once-per-second cadence summary from
|
||||
/// <c>WorldSession.Tick</c>: 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.</item>
|
||||
/// <item><c>[cmd-gate]</c> — one line per generation-gated runtime command
|
||||
/// REJECTION in <c>CurrentGameRuntimeCommandAdapter.Validate</c> (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.</item>
|
||||
/// </list>
|
||||
/// Zero steady-state cost when off: every site is behind this single bool.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public static class NetDiagnostics
|
||||
{
|
||||
/// <summary>
|
||||
/// <c>ACDREAM_PROBE_NET=1</c> — #260 outbound/command-gate probe family.
|
||||
/// </summary>
|
||||
public static bool ProbeNet { get; set; } =
|
||||
Environment.GetEnvironmentVariable("ACDREAM_PROBE_NET") == "1";
|
||||
}
|
||||
|
|
@ -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;
|
||||
|
||||
/// <summary>
|
||||
/// #260 probe: accumulate per-Tick cadence facts and emit one
|
||||
/// <c>[net-tick]</c> summary line per second.
|
||||
/// </summary>
|
||||
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;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// 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<byte> 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<byte> 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);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// #260 probe: one <c>[net-out]</c> 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.
|
||||
/// </summary>
|
||||
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;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
|
|
@ -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)
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue