Load-time attribution: the minute is the renderers' entity-make streams

Measured (loadphase markers + queue blocker dump): renderer LoadMission
31ms, model loads 0.2s -- the teal->green minute is the LoadingMission
ready-gate (IsPriorityEmpty counts timed events too) waiting out the
THREE renderers' entity-make streams: every entity/subsystem creation
posts message 3 to each Renderer receiver (classIDs 8/30/36 =
video/audio/gauge), hundreds deep per queue, draining across the whole
window (the audio renderer's share is why sound starts mid-load).

Instrumentation kept: [loadphase] markers (renderer span + busy-pass
counter) always on; GeneralEventQueue::DumpBlockers + the class-named
DumpData fallback behind BT_LOAD_DIAG=1 (hundreds of lines per load).
Optimizing the drain (batching/budget) is an open perf item --
deliberately untouched before the 8-player night.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
arcattack
2026-07-22 20:41:36 -05:00
co-authored by Claude Opus 4.8
parent 0ef5a3c4e1
commit 7b3e76db38
4 changed files with 53 additions and 1 deletions
+12
View File
@@ -437,6 +437,18 @@ phase). Plan: `~/.claude/plans/partitioned-snuggling-piglet.md`.
from take 2's commit is UNPROVEN -- the measured fact is just that loads outlive any fixed
cap; the counter design is correct under either reading. Residual: WHY loads take 1-2+ min
on the operator box (vs ~30s earlier same day) is an open perf question ([loadobj] timings).
- **WHERE THE LOAD MINUTE GOES (2026-07-22) [T2, measured]**: teal->green (egg receipt ->
WaitingForLaunch/READY) measured 58s on the operator box uncontended, ~28s on a quieter run.
Attribution (loadphase markers + queue dump): renderer LoadMission = **31ms**, model loads =
**0.2s** -- essentially ALL the time is the LoadingMission ready-gate
(`CheckLoadMessageHandler` requires `IsPriorityEmpty(MinEventPriority)`, which counts TIMED
events too) waiting out the **three renderers' entity-make streams**: every entity/subsystem
creation posts a make message (message 3) to each Renderer receiver (classIDs 8/30/36 =
video/audio/gauge), hundreds deep per queue, draining over the whole window (the audio
renderer's share is why sound starts mid-load). Optimization (batch the makes / profile
per-event cost) is an OPEN perf item -- deliberately not attempted pre-8-player-night.
Diags: `[loadphase]` markers always on; the full queue dump gates on `BT_LOAD_DIAG=1`;
`GeneralEventQueue::DumpBlockers` + the named fallback in `Event::DumpData`.
- **READY LIGHT (2026-07-22) [T2, live-verified]**: the roster showed "registered" for a
still-loading pod and a ready one alike. When the app ladder reaches WaitingForLaunch
(APP.cpp CheckLoad transition) the pod sends ONE empty route **-10** frame on its live relay
+8
View File
@@ -1377,9 +1377,17 @@ void
static int s_busy_passes = 0;
++s_busy_passes;
if ((s_busy_passes % 5) == 1)
{
DEBUG_STREAM << "[loadphase] CheckLoad: event queue still busy"
<< " (pass " << s_busy_passes << ") t=" << GetTickCount()
<< std::endl << std::flush;
// full queue dump is VERBOSE (hundreds of lines per load) --
// finding of record: the blockers are the three renderers'
// entity-make streams (message 3 for Renderer, classIDs
// 8/30/36) -- re-enable to re-verify
if (getenv("BT_LOAD_DIAG") != NULL)
eventQueue->DumpBlockers(MinEventPriority);
}
}
if (eventQueue->IsPriorityEmpty(MinEventPriority))
{
+28 -1
View File
@@ -295,7 +295,9 @@ void
else
{
Vanilla_Message:
DEBUG_STREAM << "Message " << messageToSend->messageID << " for object of classID " << target->GetClassID() << std::endl << std::flush;
DEBUG_STREAM << "Message " << messageToSend->messageID << " for "
<< (target->GetDerivation() ? target->GetDerivation()->className : "?")
<< " (classID " << target->GetClassID() << ")" << std::endl << std::flush;
}
}
@@ -718,6 +720,31 @@ Logical
return !i.GetCurrent() && !j.GetCurrent();
}
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
//
void
GeneralEventQueue::DumpBlockers(int priority)
{
Check(this);
Verify(priority >= 0 && priority < priorityLevels);
ChainIteratorOf<AbstractEvent*> pending(this[priority].pendingEvents);
AbstractEvent *event;
while ((event = pending.GetCurrent()) != NULL)
{
DEBUG_STREAM << "[loadphase] pending: " << std::flush;
event->DumpData();
pending.Next();
}
ChainIteratorOf<AbstractEvent*> timed(this[priority].timedEvents);
while ((event = timed.GetCurrent()) != NULL)
{
DEBUG_STREAM << "[loadphase] timed(+"
<< (float)(event->alarmTime - Now()) << "s): " << std::flush;
event->DumpData();
timed.Next();
}
}
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
//
Logical
+5
View File
@@ -230,6 +230,11 @@ public:
Logical
IsPriorityEmpty(int priority);
// LOAD-ATTRIBUTION DIAG (2026-07-22): name every event holding a
// priority level non-empty (the LoadingMission ready-gate blocker hunt).
void
DumpBlockers(int priority);
Logical
ProcessOneEvent(int min_priority=0);
void