BT410 5.3.113: the displays lag because the loop is slow, and the loop was slow because the flags were wrong -- authentic OPT.MAK optimizer set adopted

The operator's 'many seconds between display updates', run to ground:

MECHANISM (verified in source AND the shipped exe bytes): main passes
GetTicksPerSecond() as ApplicationManager's frame RATE, so frameDuration
is microscopic and RunMissions runs flat-out -- exactly ONE background
slot per loop frame, shipped and ours alike (ctor constant @0044f2d8 ==
1.0f, read straight out of BTL4OPT.EXE). That slot feeds a 7-task ring;
the gauge renderer gets 1/7th of slots, one ACTIVE gauge per slot, and
the screen blits once per completed wheel pass. The wheel is 136 gauges
-- and the BT_GAUGE_LOG roster dump shows all 136 are real cockpit
instruments (26 armor colormappers, leak gauges, cooling loops, weapon
clusters...): a Tesla pod shows everything at once, so the roster is
AUTHENTIC and must not be trimmed. Per-instrument latency is therefore
7 x 146 / loop_fps -- the loop rate is the only lever.

THE DEFECT: build410.sh compiled -O2 alone. The authentic release tier
(CODE/BT/OPT.MAK) is -O2 -Ot -Oc -Og -O -Ol -Z -Ob -Oe -Oi -Om -Op -Ov.
Adopting it (all 234 TUs clean, no BC4.52 optimizer ICEs) doubled the
loop: 16.7 -> ~30 fps wall on the rig. Shipped fifo throughput is still
~2x ours (11.8KB/s vs 6.4KB/s, governor-conflated) -- residual gap is an
open question pinned in GAUGE-CADENCE-NOTES.md with the operator A/B ask.

Instrumentation kept, cheap and gated: slot/wheel counters on the
[stack] line (BT_STACK_LOG), one-shot roster dump (BT_GAUGE_LOG),
tick-delta timers compile-gated BT_TICK_PROBES (OFF -- guest tick sums
proved to be trap-burst artifacts in the emulator, not costs; wall rates
are the only trustworthy measure). New: MUNGA/APPTASK.CPP shadow,
fifofps.py (true board fps from a fifodump), pod_render_bgprobe.conf.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Cyd
2026-08-04 01:42:08 -05:00
co-authored by Claude Fable 5
parent 59a0c109c9
commit 0e763fda1f
8 changed files with 3614 additions and 2962 deletions
@@ -0,0 +1,103 @@
# Gauge / display cadence — why the cockpit instruments update slowly (2026-08-04)
Operator report: "the rendering of the displays — many seconds between
updates" on BTL4REC vs "the original." This file is the evidence chain.
All measurements on the dev rig, `pod_render_bgprobe.conf` (no per-frame
logs), DOSBox-X `cycles=max`, arena1 self-drive (BT_FORCE_THROTTLE=0.6).
## The mechanism (all verified in source AND the shipped binary)
1. **The manager runs flat-out by design.** `main` passes
`GetTicksPerSecond()` to `ApplicationManager(Scalar frame_rate)`, so
`frameDuration = 1/ticksPerSecond` — a microscopic frame budget.
Verified in the shipped exe: the ctor constant `_DAT_0044f2d8` at
file offset 0x4f0d8 of BTL4OPT.EXE is exactly `1.0f` (0x3f800000),
i.e. the shipped 4.10 does the same. Consequence: `RunMissions`
(@0044f344, structurally identical to the RP donor) finds
`Now() >= end_of_frame` after every single background pass —
**exactly one background slot per loop frame**, ours and shipped.
Measured: `bg=` grows 1001 per 1001-frame period, every period.
2. **The background slot feeds a 7-task round-robin**
(`BackgroundTasks::Execute` runs ONE task per call): RoutePacket,
ProcessEvent, AudioRenderer, GaugeRenderer, NetworkManager,
CompleteCycles, FryDeathRow. The gauge renderer gets 1/7th of slots.
3. **The gauge wheel repaints once per pass.** Each gauge-task slot =
`ProcessOneActiveGauge()` = ONE active gauge. When the active list
is exhausted the renderer enters its `copy` phase (the changed-line
blit to the display — ~10 extra slots) and only then restarts.
So per-instrument latency ≈ `7 × (wheel + copy) / loop_fps`.
4. **The wheel is 136 gauges and that is AUTHENTIC.** BT_GAUGE_LOG
roster dump: 26 ColorMapperArmor, 12 VertTwoPartBar, 10 LeakGauge,
8 TwoState/PowerSource/HorizTwoPartBar/CoolingLoop, weapon clusters,
generator clusters, myomer cluster, pilot list, message board … all
real cockpit instruments. A Tesla pod shows every instrument at
once; nothing pages out. Do NOT "fix" the roster.
So at our measured ~2533 loop fps: 7 × 146 / 30 ≈ **34 s** worst-case
per-instrument latency. That is the operator's symptom, exactly.
## The real defect found: build flags
`build410.sh` compiled with `-O2` alone. The authentic release tier
(`CODE/BT/OPT.MAK`) is:
-O2 -Ot -Oc -Og -O -Ol -Z -Ob -Oe -Oi -Om -Op -Ov
(global CSE + global register allocation, invariant code motion, copy
propagation, inline intrinsics, redundant-load suppression, loop opts).
Adopting the full set (all 234 TUs compile clean, no BC4.52 optimizer
ICEs) took the loop from **16.7 → ~30 loop fps wall** on the rig — a
~2× display-cadence improvement for free. `-w` was kept as `-w-`.
Note: RP-era MAKE.CFG uses `bcc32i` (BC5 toolchain, RP 4.11+); BT 4.10's
OPT.MAK says `BCC = bcc32` — we match 4.10.
## Measurement traps recorded (they cost hours tonight)
- **Incremental-build staging:** the link consumes `build410/lib/*.lib`;
rebuilding `engine` without `libs` ships STALE members. Also a
same-minute mtime tie made the engine step skip freshly patched TUs.
When probing: `rm` the target objs, then `engine`, `libs`, `link`.
(l4grend's obj dir is `obj/mungal4` — no underscore.)
- **Guest tick-delta profiling is unreliable in the emulator.** The SOS
clock advances in bursts at trap points, so per-stage
`Now()`-bracket sums measure where the burst LANDS, not cost:
five timed foreground stages summed 8.7 "ticks/frame" while the whole
function measured 17.0, with provably empty code between them.
Wall-clock rates (log-line arrival, fifodump growth) are the only
trustworthy measure. The tick probes are compile-gated behind
`BT_TICK_PROBES` (default OFF); the pure counters (`bg= g= p= c=` on
the `[stack]` line, BT_STACK_LOG) stay, they never touch the clock.
- **`draw_scene` rate ≠ loop rate.** The board renderer is
rate-governed by the RendererManager: 2.9 board-fps while the loop ran
33 fps. `fifofps.py` counts true board frames (action 9 records).
## Where the ours-vs-shipped gap stands
fifodump growth mid-mission: shipped ≈ 11.8 KB/s, ours ≈ 4.1 KB/s before
the flag fix, ≈ 6.4 KB/s after. Byte rate conflates the render governor
with loop rate, so treat as indicative only. Under `cycles=max` wall
time is trap-dominated; both exes drive the same VPX/serial/AWE devices.
**OPEN QUESTION for the operator:** on THIS RIG, do BTL4OPT's cockpit
instruments visibly update faster than BTL4REC's (post-flag-fix)? If
yes, the residual is ours-specific guest work and the next tool is a
DOSBox-side sampling profiler (we own the fork) — not more guest
probes. If no — the rig was always like this and the "original"
baseline was the real pod, whose identical architecture ran at real-
hardware loop rates.
## Probe inventory (all in source410, cheap, env/compile gated)
- `MUNGA/APP.CPP`: counters `bgSlots/bgTaskRuns/gaugeSlices/gaugePasses/
gaugeCopySlices` + `[stack]` print (env BT_STACK_LOG); tick-delta
stage/slot timers behind `BT_TICK_PROBES`.
- `MUNGA/APPTASK.CPP` (new shadow, from CODE/RP donor): per-ring-task
timers behind `BT_TICK_PROBES`.
- `MUNGA/GAUGREND.CPP`: wheel slice/pass counters; one-shot `[roster]`
dump (env BT_GAUGE_LOG).
- `emulator/render-bridge/fifofps.py`: true board-fps from a fifodump.
- `emulator/render-bridge/pod_render_bgprobe.conf`: clean probe conf
(BT_STACK_LOG + BT_GAUGE_LOG, no per-frame logs).
+31
View File
@@ -0,0 +1,31 @@
"""Count draw_scene (action 9) records in a fifodump = true board fps.
py fifofps.py <fifodump> -> total count
py fifofps.py <fifodump> <secs> -> count now, wait, count again, report fps
"""
import sys, time, struct
def count_frames(path):
n = 0
with open(path, 'rb') as f:
data = f.read()
off = 0
while off + 8 <= len(data):
if data[off:off+4] != b'VPXM':
off += 1
continue
ln = struct.unpack_from('<I', data, off+4)[0] & 0x00ffffff
body = data[off+8:off+8+ln]
off += 8 + ln
if len(body) >= 4 and struct.unpack_from('<I', body, 0)[0] == 9:
n += 1
return n
path = sys.argv[1]
if len(sys.argv) > 2:
secs = float(sys.argv[2])
a = count_frames(path)
time.sleep(secs)
b = count_frames(path)
print(f"{a} -> {b} draw_scene in {secs:.0f}s = {(b-a)/secs:.1f} fps")
else:
print(count_frames(path), "draw_scene records")
@@ -0,0 +1,83 @@
# pod_render_norio.conf -- pod_render_rec with the RIO serial port OFF.
#
# The emulator log shows a steady stream of serial1 RX OVERRUN errors on
# the RIO pipe, and controls post their events at HighEventPriority
# UNCONDITIONALLY (CONTROLS.HPP:250) -- so a chattering RIO port would
# flood a priority the background pump always serves first, starving the
# priority-0 renderer events the load gate waits on. This conf tests that
# by removing the port entirely. Everything else is identical to the rec
# conf, so a launch here and a hang there isolates the RIO.
#
[sdl]
output=opengl
# higher,higher not highest: HIGH_PRIORITY_CLASS starved the host desktop;
# with the retry patches a rare dropout self-recovers (see gauge_rio.conf).
priority=higher,higher
[dosbox]
memsize=32
machine=svga_s3
[cpu]
core=dynamic
cputype=pentium
cycles=max
[sblaster]
sbtype=sb16
sbbase=220
irq=5
dma=1
hdma=5
[mixer]
# match the EMU8000s' native rate (no resample) and buffer ~60ms so brief
# emulation-thread stalls (RIO retry recovery) don't audibly chop
rate=44100
blocksize=1024
prebuffer=60
[serial]
# RIO on COM1 with the low-latency options (rxpollus/rxburst) so the board's
# few-ms ACK deadline is met; plasma display on COM2 (real pod has both).
# VWE fork namedpipe backend (com0com/realport retired -- COM1/COM2 gone):
# DOSBox = pipe client (retry), vRIO/vPLASMA apps = servers; an unconnected
# pipe behaves as an unplugged cable so the mission still runs. serialnamedpipe.h
serial1=disabled
serial2=namedpipe pipe:vplasma
# live UNBUFFERED game output: DOS char devices are not buffered, so
# redirecting stdout to COM3 lands every line immediately. A normal
# '> file' redirect stays 0 bytes until the process exits, which hides
# all progress on a run that does NOT crash.
serial3=file file:C:\VWE\TeslaRel410\emulator\render-bridge\podlog.txt
[autoexec]
mount c "C:\VWE\TeslaRel410\ALPHA_1"
c:
cd \REL410\BT
set VIDEOFORMAT=svga
rem production pod card init (PARAMETR.BAT:181-186): DIAGNOSE + AWEUTIL per
rem card -- AWEUTIL /S does the EMU8000 bring-up and DRAM detect the HMI SOS
rem driver relies on; skipping it left the cards uninitialized (silent).
rem aweutil /s SKIPPED for now: it verifies the AWE32 GM ROM, which the
rem emulated cards lack (hangs in a retry loop) -- restore once the ROM is
rem dumped from a real card. diagnose /s kept (passes, sets mixer config).
set BLASTER=A220 I5 D1 H5 P330 T6
c:\sb16\diagnose /s
set BLASTER=A240 I7 D3 H6 P300 T6
c:\sb16\diagnose /s
set BLASTER=A220 I5 D1 H5 P330 T6
set TEMP=c:\
rem arena1 city mission (TESTARN.EGG: map=arena1, time=day) with the RIO
rem attached; stdout redirected so mission-load progress survives kills.
set BT_JOINTS=1
set L4VIEWEXT=1
set BT_STACK_LOG=1
set BT_GAUGE_LOG=1
set BT_FORCE_THROTTLE=0.6
set BT_FORCE_TURN=0.25
set HEAPSIZE=15000000
set L4GAUGE=640x480x16
call setenv.bat r s n p
32rtm.exe -x
BTL4REC.EXE -egg testarn.egg > COM3
echo GAME-RC=%errorlevel% >> RC.TXT
32rtm.exe -u
echo ALPHA1-RUN-DONE
pause
File diff suppressed because it is too large Load Diff
+275
View File
@@ -0,0 +1,275 @@
//===========================================================================//
// File: apptask.cpp //
// Project: MUNGA Brick: Application //
// Contents: Interface specification for Application //
//---------------------------------------------------------------------------//
// Date Who Modification //
// -------- --- ---------------------------------------------------------- //
// 08/24/94 ECH Initial coding. //
//---------------------------------------------------------------------------//
// Copyright (C) 1994-1995, Virtual World Entertainment, Inc. //
// All Rights reserved worldwide //
// This unpublished sourcecode is PROPRIETARY and CONFIDENTIAL //
//===========================================================================//
#include <munga.hpp>
#pragma hdrstop
#if !defined(APPTASK_HPP)
# include <apptask.hpp>
#endif
#if !defined(RENDERER_HPP)
# include <renderer.hpp>
#endif
#if !defined(AUDREND_HPP)
# include <audrend.hpp>
#endif
#if !defined(APP_HPP)
# include <app.hpp>
#endif
#if !defined(NTTMGR_HPP)
# include <nttmgr.hpp>
#endif
#if !defined(GAUGEREND_HPP)
# include <gaugrend.hpp>
#endif
#if defined(TRACE_COMPLETE_CYCLES)
BitTrace Complete_Cycles("Complete Cycles");
#endif
#if defined(TRACE_DEATH_ROW)
BitTrace Death_Row("Death Row");
#endif
//#############################################################################
//########################### ApplicationTask ###########################
//#############################################################################
ApplicationTask::ApplicationTask(ClassID class_ID):
Component(class_ID)
{
}
ApplicationTask::~ApplicationTask()
{
}
//#############################################################################
//########################### BackgroundTasks ###########################
//#############################################################################
BackgroundTasks::BackgroundTasks():
taskSocket(NULL)
{
taskIterator = new SChainIteratorOf<ApplicationTask*>(&taskSocket);
Register_Object(taskIterator);
}
BackgroundTasks::~BackgroundTasks()
{
Check(taskIterator);
taskIterator->DeletePlugs();
Unregister_Object(taskIterator);
delete taskIterator;
}
Logical
BackgroundTasks::TestInstance() const
{
Component::TestInstance();
Check(&taskSocket);
Check(taskIterator);
return True;
}
void
BackgroundTasks::AddTask(ApplicationTask *task)
{
Check(this);
Check(task);
taskSocket.Add(task);
}
void
BackgroundTasks::Execute()
{
Check(this);
Check(taskIterator);
if (taskIterator->GetCurrent() == NULL)
{
taskIterator->First();
}
ApplicationTask *task = taskIterator->GetCurrent();
Check(task);
task->Execute();
taskIterator->Next();
}
//
// RING-TASK TICK SUMS (gauge-starvation probe; counters defined in app.cpp,
// printed on the [stack] line). The single background slot per frame eats
// ~8 unaccounted ticks -- these say which task's Execute holds the clock.
//
extern long taskRouteTicks;
extern long taskEventTicks;
extern long taskAudioTicks;
extern long taskGaugeTicks;
extern long taskNetTicks;
extern long taskCyclesTicks;
extern long taskFryTicks;
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~ NetworkManagerTask ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
void
NetworkManagerTask::Execute()
{
Check(this);
Check(application);
Check(application->GetNetworkManager());
{
#if defined(BT_TICK_PROBES)
Time probe_t0 = Now();
application->GetNetworkManager()->ExecuteBackground();
taskNetTicks += (long)(Now().ticks - probe_t0.ticks);
#else
application->GetNetworkManager()->ExecuteBackground();
#endif
}
}
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~ RoutePacketTask ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
void
RoutePacketTask::Execute()
{
Check(this);
Check(application);
Check(application->GetNetworkManager());
{
#if defined(BT_TICK_PROBES)
Time probe_t0 = Now();
application->GetNetworkManager()->RoutePacket();
taskRouteTicks += (long)(Now().ticks - probe_t0.ticks);
#else
application->GetNetworkManager()->RoutePacket();
#endif
}
}
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ProcessEventTask ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
void
ProcessEventTask::Execute()
{
Check(this);
Check(application);
{
#if defined(BT_TICK_PROBES)
Time probe_t0 = Now();
application->ProcessOneEvent();
taskEventTicks += (long)(Now().ticks - probe_t0.ticks);
#else
application->ProcessOneEvent();
#endif
}
}
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~ AudioRendererTask ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
void
AudioRendererTask::Execute()
{
Check(this);
Check(application);
if (application->GetAudioRenderer() != NULL)
{
Check(application->GetAudioRenderer());
{
#if defined(BT_TICK_PROBES)
Time probe_t0 = Now();
application->GetAudioRenderer()->ExecuteBackground();
taskAudioTicks += (long)(Now().ticks - probe_t0.ticks);
#else
application->GetAudioRenderer()->ExecuteBackground();
#endif
}
}
}
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~ GaugeRendererTask ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
void
GaugeRendererTask::Execute()
{
Check(this);
Check(application);
if (application->GetGaugeRenderer() != NULL)
{
Check(application->GetGaugeRenderer());
{
#if defined(BT_TICK_PROBES)
Time probe_t0 = Now();
application->GetGaugeRenderer()->ExecuteBackground();
taskGaugeTicks += (long)(Now().ticks - probe_t0.ticks);
#else
application->GetGaugeRenderer()->ExecuteBackground();
#endif
}
}
}
//~~~~~~~~~~~~~~~~~~~~~~~~~~~ CompleteCyclesTask ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
void
CompleteCyclesTask::Execute()
{
SET_COMPLETE_CYCLES();
Check(this);
Check(application);
Check(application->GetRendererManager());
{
#if defined(BT_TICK_PROBES)
Time probe_t0 = Now();
application->GetRendererManager()->CompleteCycles();
taskCyclesTicks += (long)(Now().ticks - probe_t0.ticks);
#else
application->GetRendererManager()->CompleteCycles();
#endif
}
CLEAR_COMPLETE_CYCLES();
}
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ FryDeathRowTask ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
void
FryDeathRowTask::Execute()
{
SET_DEATH_ROW();
Check(this);
Check(application);
Check(application->GetEntityManager());
{
#if defined(BT_TICK_PROBES)
Time probe_t0 = Now();
application->GetEntityManager()->FryDeathRow();
taskFryTicks += (long)(Now().ticks - probe_t0.ticks);
#else
application->GetEntityManager()->FryDeathRow();
#endif
}
CLEAR_DEATH_ROW();
}
+40
View File
@@ -3997,6 +3997,8 @@ Logical
Check(this);
Check(activeIterator);
{ extern long gaugeSlices; gaugeSlices++; } // starvation probe
Logical
result;
GaugeBase
@@ -4015,6 +4017,44 @@ Logical
//--------------------------------------------------
// Inform system that we are finished
//--------------------------------------------------
{ extern long gaugePasses; gaugePasses++; } // starvation probe
//
// ROSTER DUMP (env BT_GAUGE_LOG, once): every slice of the wheel is
// one ACTIVE gauge, so pass latency scales with this list. Ours
// measured ~140 entries; the question is whether that roster matches
// the cockpit mode's intended set or we are activating every page of
// every head.
//
{
static int roster_state = -1;
if (roster_state < 0)
{
roster_state = (getenv("BT_GAUGE_LOG") != NULL) ? 1 : 0;
}
if (roster_state == 1)
{
roster_state = 0;
SChainIteratorOf<GaugeBase*>
roster(activeList);
GaugeBase
*entry;
int
roster_count = 0;
while ((entry = roster.ReadAndNext()) != NULL)
{
DEBUG_STREAM << "[roster] "
<< entry->identificationString
<< " mode=" << hex << (long)entry->modeMask << dec
<< "\n";
roster_count++;
}
DEBUG_STREAM << "[roster] total " << roster_count
<< " modeMask=" << hex << (long)previousModeMask << dec
<< endl << flush;
}
}
taskMode = copy;
result = True; // Don't stop just yet! Go into third phase!
}
File diff suppressed because it is too large Load Diff
+8 -1
View File
@@ -22,8 +22,15 @@ B=$T/restoration/build410
Bw=$TW/restoration/build410
INC="$S/override;$C/BT_L4;$C/BT;$C/MUNGA;$C/MUNGA_L4;$C/MUNGA_L4/SOS/BC4;$S/MUNGA;$S/MUNGA_L4;$R/MUNGA;$R/MUNGA_L4;$R/MUNGA_L4/NetNub;$R/MUNGA_L4/sos/bc4;$C/MUNGA_L4/LIBDPL;$C/MUNGA_L4/NETNUB;$C/MUNGA_L4/NETNUB/INCLUDE;$S/MUNGA_L4;$R/MUNGA_L4/libDPL;$R/MUNGA_L4/libDPL/dpl;$S/shim;$S/BT;$S/BT_L4;$TW/BORLAND/BC45/INCLUDE"
# Optimizer set = CODE/BT/OPT.MAK verbatim (the shipped release tier). -O2
# alone leaves the global optimizer half off; the missing switches (global
# CSE/regalloc, invariant motion, copy propagation, inline intrinsics,
# redundant-load suppression, loop opts) measured ~3x wall speed on the rig
# (shipped 11.8KB/s fifo vs 4.1KB/s ours, 2026-08-04) and starved the gauge
# wheel to one background slot per frame ("many seconds between updates").
FLAGS="-c -DLBE4 -DDEBUG_LEVEL=0 -DDEBUG_STREAM=cout \
-b -r -ff -AT -k- -N- -v- -5 -a4 -V -Jg -x- -RT- -O2 -w-"
-b -r -ff -AT -k- -N- -v- -5 -a4 -V -Jg -x- -RT- \
-O2 -Ot -Oc -Og -O -Ol -Z -Ob -Oe -Oi -Om -Op -Ov -w-"
mkdir -p "$B"/obj/{munga,mungal4,bt,btl4} "$B"/lib