From 56ca2f5c13234ecd805b92b07d8ba003fc569db4 Mon Sep 17 00:00:00 2001 From: arcattack Date: Thu, 23 Jul 2026 08:51:14 -0500 Subject: [PATCH] Mission loads 72s -> 4s: the wait screen was GPU-syncing every idle frame The operator challenged the "inevitable ~minute" load (Task Manager showed idle CPU) and was right. Measured chain: - A/B same box/egg: dev 7s, +glass 30s, +BT_DEV_GAUGES 72s+. - Drain census: identical ~560-event make streams; 190 events/s in dev vs a metronomic 7/s in the console shape -- the loop, not the events. - Stack sampling: 4/6 samples inside ExecuteIdle's wait-screen paint -- GDI GetDC/FillRect on the D3DPOOL_DEFAULT offscreen surface forces a full GPU pipeline sync (~140ms/frame at glass window size). The 2026-07-22 flicker fix traded a cosmetic bug for a 25x load throttle, worst on the operator box (bigger window + gauge-window GPU work), with idle CPU because a GPU-sync stall isn't compute. Fix (ExecuteIdle): the staging surface is D3DPOOL_SYSTEMMEM (GetDC is pure CPU; survives Reset for free) uploaded via UpdateSurface, and a change gate skips the whole idle frame unless the spinner phase (12.5Hz) or state text changed -- between paints the loop runs free. Result: console-shape load 72s+ -> 4.1s (BEGIN -> READY), drain at 345 events/s; every pod benefits (same code), and the all-ready launch gate now waits on a seconds-scale slowest loader. Permanent pre-run diagnostics kept: the drain census + >50ms slow-event lines (EVENT.cpp, stand down at scene-live; slow-event identity captured BEFORE Process -- Receiver::Receive(Event*) deletes the event). Co-Authored-By: Claude Opus 4.8 (1M context) --- context/multiplayer.md | 21 +++++++++++++++- engine/MUNGA/EVENT.cpp | 49 +++++++++++++++++++++++++++++++++++++ engine/MUNGA_L4/L4VIDEO.cpp | 43 +++++++++++++++++++++++++------- 3 files changed, 103 insertions(+), 10 deletions(-) diff --git a/context/multiplayer.md b/context/multiplayer.md index 90c80e7..b6bb068 100644 --- a/context/multiplayer.md +++ b/context/multiplayer.md @@ -437,7 +437,26 @@ 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 -> +- **THE LOAD MINUTE -- SOLVED (2026-07-23) [T2, measured end-to-end]**: the operator challenged + the "inevitable ~minute" claim (idle CPU in Task Manager) and was RIGHT. A/B on the same + box/egg: dev profile 7s, +glass 30s, +BT_DEV_GAUGES 72s+ -- the layers, not the machine. + Drain census (`[loadphase] drained N events/s`, EVENT.cpp pre-run): IDENTICAL ~560-event + streams, 190/s in dev vs a metronomic **7/s** in the console shape. Stack sampling (cdb, + 6 samples): 4/6 inside ExecuteIdle's wait-screen paint -- **GDI GetDC/FillRect on the + D3DPOOL_DEFAULT offscreen surface forces a full GPU pipeline sync (~140ms/frame at glass + window size)**, i.e. the 2026-07-22 flicker fix traded a cosmetic bug for a 25x load + throttle (bigger glass window + gauge-window GPU work made it worst on the operator box; + idle CPU because a GPU sync stall isn't compute). FIX (L4VIDEO ExecuteIdle): the staging + surface is now **D3DPOOL_SYSTEMMEM** (GetDC = pure CPU) uploaded via `UpdateSurface` + (StretchRect can't take sysmem), and a **change gate** skips the entire idle frame unless + the spinner phase (12.5Hz) or text changed -- between paints the loop runs free. RESULT: + console-shape load **72s+ -> 4.1s** (BEGIN->READY), drain 345 events/s; benefits EVERY pod + (same code everywhere) + the all-ready gate now waits on a seconds-scale slowest loader. + The earlier "renderers' entity-make streams are the minute" reading was the RIGHT queue but + the WRONG cost: the events were cheap; the loop offering them was throttled. Diagnostics + kept permanently: drain census + >50ms slow-event lines (EVENT.cpp, pre-run only, stand + down at scene-live). +- **WHERE THE LOAD MINUTE GOES (2026-07-22) [T2, measured -- superseded above]**: 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 diff --git a/engine/MUNGA/EVENT.cpp b/engine/MUNGA/EVENT.cpp index 7d40221..21db6ae 100644 --- a/engine/MUNGA/EVENT.cpp +++ b/engine/MUNGA/EVENT.cpp @@ -756,9 +756,58 @@ Logical AbstractEvent *event=PeekAtNextEvent(min_priority); if (event) { + // pre-run slow-event profiler (loadab investigation): name any event + // whose Process takes >50ms. Identity captured BEFORE Process -- + // Receiver::Receive(Event*) DELETES the event (RECEIVER.cpp:114). + // Stands down once the scene presents. + extern Logical gBTSceneHasPresented; + unsigned long slow_t0 = 0; + int slow_msg = -1; + if (!gBTSceneHasPresented) + { + slow_t0 = GetTickCount(); + if (event->messageToSend != NULL) + slow_msg = (int)event->messageToSend->messageID; + } SET_PROCESS_EVENT(); event->Process(); CLEAR_PROCESS_EVENT(); + if (!gBTSceneHasPresented && slow_t0 != 0) + { + unsigned long took = GetTickCount() - slow_t0; + if (took > 50) + { + DEBUG_STREAM << "[loadphase] SLOW event " << took + << "ms msgID=" << slow_msg << std::endl << std::flush; + } + } + // LOAD-DRAIN RATE (loadab investigation 2026-07-23): pre-run only, + // a 1 Hz census of events processed -- distinguishes "more events" + // from "slower per-event work" across config layers. Standing down + // permanently once the scene presents (zero hot-path cost in-game + // beyond one predicted branch). + { + extern Logical gBTSceneHasPresented; + if (!gBTSceneHasPresented) + { + static unsigned long s_windowStart = 0; + static long s_windowCount = 0; + static long s_totalCount = 0; + ++s_windowCount; + ++s_totalCount; + unsigned long now_ms = GetTickCount(); + if (s_windowStart == 0) + s_windowStart = now_ms; + if (now_ms - s_windowStart >= 1000) + { + DEBUG_STREAM << "[loadphase] drained " << s_windowCount + << " events/s (total " << s_totalCount << ")" + << std::endl << std::flush; + s_windowStart = now_ms; + s_windowCount = 0; + } + } + } return True; } return False; diff --git a/engine/MUNGA_L4/L4VIDEO.cpp b/engine/MUNGA_L4/L4VIDEO.cpp index 0ce0f71..8886bb8 100644 --- a/engine/MUNGA_L4/L4VIDEO.cpp +++ b/engine/MUNGA_L4/L4VIDEO.cpp @@ -8936,13 +8936,20 @@ void DPLRenderer::ExecuteIdle() hr = mDevice->EndScene(); // The waiting screen (join/join_lan UX fix 2026-07-22; FLICKER fix - // 2026-07-22): paint the text + spinner INTO the backbuffer via the - // surface's GDI handle BEFORE Present, so the presented frame already - // carries the overlay -- the old paint-AFTER-Present alternated a black - // D3D frame with the GDI redraw and visibly flickered during loads. - // GetDC-on-backbuffer failure (unusual formats) falls back to the old - // window-DC paint. + // 2026-07-22; LOAD-SPEED fix 2026-07-23): paint the text + spinner INTO + // the presented frame -- but NEVER via GDI on a DEFAULT-pool surface + // per frame: GetDC/FillRect on a GPU surface forces a full pipeline + // sync (~140ms/frame on the operator GPU at glass size), which throttled + // the pre-run loop to ~7 iterations/s and multiplied every mission load + // (stack-sampled: 4/6 samples inside the overlay FillRect/GetDC; drain + // census: same 560 events at 190/s dev vs 7/s glass+gauges). Now: the + // GDI paint goes to a SYSTEMMEM staging surface (GetDC there is pure + // CPU), uploaded with UpdateSurface, and the whole frame is SKIPPED + // unless the spinner phase or text changed (12.5 Hz) -- between paints + // the loop runs free and the event queue drains at full speed. { + const char *wait_line1_probe = ""; // (filled below; declared for the gate) + (void)wait_line1_probe; const char *wait_line1 = "WAITING FOR MISSION ASSIGNMENT"; const char *wait_line2 = "the operator starts the session from the console"; switch (application ? application->GetApplicationState() : -1) @@ -8963,6 +8970,20 @@ void DPLRenderer::ExecuteIdle() // OFFSCREEN PLAIN surface (GetDC always works there) and StretchRect // it onto the backbuffer pre-Present. The cache is D3DPOOL_DEFAULT, // released on device loss below. + // CHANGE GATE: repaint/present only when the spinner phase or the + // text changes -- otherwise skip the whole idle frame (the last + // presented image stays on screen; nothing else draws pre-run). + { + static unsigned long s_lastPhase = 0xFFFFFFFF; + static const char *s_lastLine1 = NULL; + unsigned long phase = (GetTickCount() / 80UL) % 12UL; + if (phase == s_lastPhase && wait_line1 == s_lastLine1) + { + return; // nothing changed: free the loop + } + s_lastPhase = phase; + s_lastLine1 = wait_line1; + } Logical painted_in_backbuffer = False; IDirect3DSurface9 *backbuffer = NULL; if (SUCCEEDED(mDevice->GetBackBuffer(0, 0, D3DBACKBUFFER_TYPE_MONO, @@ -8984,8 +9005,10 @@ void DPLRenderer::ExecuteIdle() } if (mWaitOverlaySurface == NULL) { + // SYSTEMMEM: GetDC is pure CPU (no GPU sync) and the + // surface survives device Reset for free. mDevice->CreateOffscreenPlainSurface(desc.Width, - desc.Height, D3DFMT_X8R8G8B8, D3DPOOL_DEFAULT, + desc.Height, D3DFMT_X8R8G8B8, D3DPOOL_SYSTEMMEM, &mWaitOverlaySurface, NULL); } HDC surface_dc = NULL; @@ -8996,8 +9019,10 @@ void DPLRenderer::ExecuteIdle() BTWaitScreenPaintDC(surface_dc, (int)desc.Width, (int)desc.Height, wait_line1, wait_line2); mWaitOverlaySurface->ReleaseDC(surface_dc); - if (SUCCEEDED(mDevice->StretchRect(mWaitOverlaySurface, - NULL, backbuffer, NULL, D3DTEXF_NONE))) + // SYSTEMMEM -> DEFAULT is UpdateSurface's job + // (StretchRect cannot take a sysmem source). + if (SUCCEEDED(mDevice->UpdateSurface(mWaitOverlaySurface, + NULL, backbuffer, NULL))) { painted_in_backbuffer = True; }