erik/acdream
1
0
Fork 0
Code Issues Pull requests Projects Releases 6 Packages Wiki Activity Actions

perf #418: publish landblocks under the meter, not one per streaming tick

Browse source 
Phase-1 measurement (new [publish-timing]/[stream-tick] probe surfaces,
ACDREAM_PROBE_REVEAL_TIMING=1) refuted the ~31 ms-per-admission
hypothesis: the hold runs at ~64 fps with the streaming tick at ~32 Hz,
the whole 625-block window costs only ~500 ms of publication CPU (far
blocks ~0.17 ms, near 2-43 ms), and steady state showed ZERO meter
yields with ~0.22 ms of the 2 ms budget used - yet exactly one block
published per tick against a ~400-deep completion queue.

The real limiter: Runtime's collision-generation activation is a
deliberate two-poll transaction (the first
TryAcquireCollisionPrefixMutationPermission poll parks residents and
refuses by design), and LandblockPresentationPipeline.Advance's metered
arm returned Completed=false on ANY nonterminal commit, which
DrainAndApply treats as end-of-frame. One landblock per 32 Hz tick =
the flat 32/s, with the authored budget ~90% idle.

Fix: the metered arm now uses the same Runtime-owned gate the unmetered
arm and the synchronous CompletePublication API always used
(CanContinueMutationSynchronously). The second poll runs in the same
frame under the same meter, so the unchanged 2 ms elapsed-time ceiling
is now genuinely the authoritative per-frame bound; with any real debt
(live residents parked mid-game, pending withdrawals, dispatch backlog)
publication defers to the next frame exactly as before. No budget
values change, no reveal-gate/readiness change, and the streamed result
is byte-identical - only the frame scheduling of identical operations.

Measured A/B (this binary, two runs): totalMs 12689 / 12734 vs baseline
26728/27395/27503; loaded slope 32/s -> bursts of 100-360/s, 625/625 in
~6-7 s vs ~23 s. The remaining ~12.7 s floor is fully attributed in
docs/ISSUES.md: ~8 s of real budgeted readiness work plus retail's
authored tunnel exit (TunnelContinue 2-5 s + two 1 s fades, golden
constants), so the <12 s acceptance needs a lead decision on the
hold-time budget, not another hidden limiter.

New regression pin:
MeteredLoaded_NonterminalCommitWithoutDebt_CompletesInOneMeteredAdvance.
Gates: Release build 0 errors; App tests 5576/3 skips/0 failed;
Runtime tests 1756/0.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Erik 2026-08-17 20:11:35 +02:00
parent 45f379560a
commit 11106c70e7
6 changed files with 408 additions and 5 deletions
Download patch file Download diff file Expand all files Collapse all files

227
src/AcDream.App/Streaming/PublicationTimingProbe.cs Normal file
View file

@ -0,0 +1,227 @@
using System.Diagnostics;
using System.Text;
namespace AcDream.App.Streaming;
/// <summary>
/// Per-stage wall-clock accumulator for ONE landblock publication transaction
/// (#418 measurement). Created only when
/// <see cref="StreamingDiagnostics.ProbeRevealTiming"/> is set; a null
/// instance on the transaction means the probe is off and costs one null
/// check per stage operation.
/// </summary>
internal sealed class PublicationStageTimings
{
private readonly Dictionary<string, (long Ticks, int Count)> _stages = new();
private long _totalTicks;
public long TotalTicks => _totalTicks;
public void Add(string stage, long ticks)
{
if (ticks < 0)
ticks = 0;
_totalTicks += ticks;
_stages[stage] = _stages.TryGetValue(stage, out (long Ticks, int Count) prior)
? (prior.Ticks + ticks, prior.Count + 1)
: (ticks, 1);
}
public IReadOnlyDictionary<string, (long Ticks, int Count)> Stages => _stages;
}
/// <summary>
/// <c>ACDREAM_PROBE_REVEAL_TIMING=1</c> sibling surface for issue #418:
/// attributes ONE admitted landblock's update-thread publication cost per
/// stage. Emits:
///
/// <list type="bullet">
/// <item><c>[publish-timing] lb=…</c> — one line per completed landblock
/// publication with the total milliseconds and a per-stage
/// <c>name:ms/count</c> breakdown (stages sorted by cost).</item>
/// <item><c>[publish-timing] CUMULATIVE …</c> — every 64 publications, the
/// running per-stage totals across all completed publications.</item>
/// </list>
///
/// It also accumulates the per-frame streaming-tick elapsed time so
/// <see cref="RevealTimingProbe"/>'s 1 Hz progress line can report how much
/// of each wall-clock second the streaming tick consumed (with the observed
/// render-frame count, this verifies or refutes the ~31 ms/frame
/// prediction). Diagnostic-only: no behavior change, never active unless the
/// probe env is set. All access happens on the window thread (the streaming
/// controller and render frame graph share it).
/// </summary>
internal static class PublicationTimingProbe
{
private const int CumulativeEmitInterval = 64;
private static readonly Dictionary<string, (long Ticks, int Count)>
s_cumulativeStages = new();
private static readonly Dictionary<string, int> s_tickWindowYieldReasons =
new();
private static long s_cumulativeTicks;
private static int s_publications;
private static double s_tickWindowSumMs;
private static double s_tickWindowMaxMs;
private static int s_tickWindowCount;
private static int s_tickWindowYields;
private static int s_tickWindowOperations;
private static int s_tickWindowAdmissions;
private static int s_lastWorkerBacklog;
private static int s_lastQueuedCompletions;
public static bool Enabled => StreamingDiagnostics.ProbeRevealTiming;
/// <summary>Per-transaction accumulator, or null when the probe is off.</summary>
public static PublicationStageTimings? CreateTimings() =>
Enabled ? new PublicationStageTimings() : null;
/// <summary>
/// Reports one completed landblock publication and folds its stages into
/// the cumulative rollup.
/// </summary>
public static void EmitPublication(
uint landblockId,
string kind,
PublicationStageTimings timings)
{
s_publications++;
s_cumulativeTicks += timings.TotalTicks;
var line = new StringBuilder(256);
line.Append("[publish-timing] lb=0x")
.Append(landblockId.ToString("X8"))
.Append(" kind=").Append(kind)
.Append(" totalMs=")
.Append(ToMs(timings.TotalTicks).ToString("F2"))
.Append(" stages=");
AppendStagesByCost(line, timings.Stages);
Console.WriteLine(line.ToString());
foreach ((string stage, (long ticks, int count)) in timings.Stages)
{
s_cumulativeStages[stage] = s_cumulativeStages.TryGetValue(
stage,
out (long Ticks, int Count) prior)
? (prior.Ticks + ticks, prior.Count + count)
: (ticks, count);
}
if (s_publications % CumulativeEmitInterval == 0)
EmitCumulative();
}
private static void EmitCumulative()
{
var line = new StringBuilder(256);
line.Append("[publish-timing] CUMULATIVE landblocks=")
.Append(s_publications)
.Append(" totalMs=")
.Append(ToMs(s_cumulativeTicks).ToString("F0"))
.Append(" stages=");
AppendStagesByCost(line, s_cumulativeStages);
Console.WriteLine(line.ToString());
}
private static void AppendStagesByCost(
StringBuilder line,
IReadOnlyDictionary<string, (long Ticks, int Count)> stages)
{
bool first = true;
foreach ((string stage, (long ticks, int count)) in
stages.OrderByDescending(static pair => pair.Value.Ticks))
{
if (!first)
line.Append(',');
first = false;
line.Append(TrimStagePrefix(stage))
.Append(':')
.Append(ToMs(ticks).ToString("F2"))
.Append('/')
.Append(count);
}
}
/// <summary>
/// Every pipeline stage name starts with <c>publication-</c>; dropping the
/// shared prefix keeps the per-landblock line readable.
/// </summary>
private static string TrimStagePrefix(string stage) =>
stage.StartsWith("publication-", StringComparison.Ordinal)
? stage["publication-".Length..]
: stage;
/// <summary>
/// Records one <see cref="StreamingController.Tick"/> frame into the
/// current 1 Hz reporting window: elapsed time, meter operation/yield
/// counts, admissions, the reason the meter last refused work, and the
/// end-of-tick worker/queue backlogs.
/// </summary>
public static void ObserveStreamingTick(
in StreamingWorkMeterSnapshot snapshot,
int workerBacklog,
int queuedCompletions)
{
s_tickWindowCount++;
s_tickWindowSumMs += snapshot.ElapsedMilliseconds;
if (snapshot.ElapsedMilliseconds > s_tickWindowMaxMs)
s_tickWindowMaxMs = snapshot.ElapsedMilliseconds;
s_tickWindowYields += snapshot.YieldCount;
s_tickWindowOperations += snapshot.Operations;
s_tickWindowAdmissions += snapshot.Used.CompletionAdmissions;
if (snapshot.YieldCount > 0
&& snapshot.LastLimit != StreamingWorkLimit.None
&& snapshot.LastStage is { } stage)
{
string reason = $"{stage}/{snapshot.LastLimit}";
s_tickWindowYieldReasons[reason] =
s_tickWindowYieldReasons.TryGetValue(reason, out int prior)
? prior + 1
: 1;
}
s_lastWorkerBacklog = workerBacklog;
s_lastQueuedCompletions = queuedCompletions;
}
/// <summary>
/// Emits and resets the current streaming-tick reporting window as one
/// <c>[stream-tick]</c> line. Called by <see cref="RevealTimingProbe"/>'s
/// 1 Hz progress path.
/// </summary>
public static void EmitStreamingTickWindow()
{
var line = new StringBuilder(192);
line.Append("[stream-tick] ticks=").Append(s_tickWindowCount)
.Append(" sumMs=").Append(s_tickWindowSumMs.ToString("F1"))
.Append(" maxMs=").Append(s_tickWindowMaxMs.ToString("F1"))
.Append(" ops=").Append(s_tickWindowOperations)
.Append(" yields=").Append(s_tickWindowYields)
.Append(" admissions=").Append(s_tickWindowAdmissions)
.Append(" workerBacklog=").Append(s_lastWorkerBacklog)
.Append(" queuedCompletions=").Append(s_lastQueuedCompletions)
.Append(" yieldReasons=");
bool first = true;
foreach ((string reason, int count) in
s_tickWindowYieldReasons.OrderByDescending(
static pair => pair.Value))
{
if (!first)
line.Append(',');
first = false;
line.Append(reason).Append('x').Append(count);
}
if (first)
line.Append("none");
Console.WriteLine(line.ToString());
s_tickWindowCount = 0;
s_tickWindowSumMs = 0;
s_tickWindowMaxMs = 0;
s_tickWindowYields = 0;
s_tickWindowOperations = 0;
s_tickWindowAdmissions = 0;
s_tickWindowYieldReasons.Clear();
}
private static double ToMs(long stopwatchTicks) =>
stopwatchTicks * 1000.0 / Stopwatch.Frequency;
}