vwemirror/BT411
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

#149: measure the filed suspect -- the #141 segment sweep is EXONERATED; ship [segperf] telemetry

Browse Source 
A/B on identical 2-node beam-heavy runs (scratchpad/night14/segperf.sh),
BT_BEAM_SEGFRESH=1 (swept behaviour) vs =0 (pre-sweep compose at the beam
site, the only per-frame swept call):

                    fresh(swept)   legacy(pre-sweep)
  rstat blocks>50ms       0              0
  maxDraw worst         730ms          646ms      (mission-load spike, BOTH)
  segperf dirty-passes   38/s            4/s      <- the sweep DOES multiply
  segperf accessor ms   0.97/s          0.57/s    <- ...by 0.4 ms/s.  Noise.

So the invalidation-storm hypothesis I filed on #149 is wrong by three orders
of magnitude, and Oracle's sustained 50-104ms stall window does NOT reproduce
on this rig at all.  Refusing to guess a third time: the build now carries the
telemetry to answer it on the machine that actually regresses --

  [segperf] calls= dirty= ms=   printed beside every [rstat] window under
  BT_PERF_LOG (JMOVER counters; two integer increments when unset), and
  BT_BEAM_SEGFRESH=0 remains as a one-env A/B for the beam site.

Default stays FRESH (the swept accessor): its measured cost is trivial and it
is the correctness-cautious side while the peer-beam-staleness question is
unmeasured.

Next for #149: Oracle runs one session with BT_PERF_LOG=1.  If [segperf] ms is
large inside his stalled windows, segment work is implicated on HIS
configuration and BT_BEAM_SEGFRESH=0 gives the immediate A/B; if it is small
(as here), the stall is elsewhere in the 817->857 delta and we hunt with his
numbers instead of my theories.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_018SgmXGNMXavXiafKXf9MDC
This commit is contained in:
Joe DiPrima
2026-08-09 16:46:10 -05:00
co-authored by Claude Opus 5
parent 84f8b1c415
commit a77c5a1407
4 changed files with 122 additions and 1 deletions
Download Patch File Download Diff File Expand all files Collapse all files
engine/MUNGA/JMOVER.cpp
+21
View File
@@ -117,6 +117,16 @@ EntitySegment*
}
//~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
// #149 perf telemetry (BT_PERF_LOG; counters cost two increments when unset).
// gBTSegWDirty counts the EXPENSIVE arm -- the mark-every-segment pass that
// invalidates the whole table -- separately from plain calls, because the #141
// sweep put this accessor on per-frame weapon/beam paths and the open question
// is whether that multiplied the dirty-pass rate (each pass forces the next
// query of EVERY segment to re-derive its parent chain).
int gBTSegWCalls = 0;
int gBTSegWDirty = 0;
double gBTSegWMs = 0.0;
//
void
JointedMover::GetSegmentToWorld(
@@ -125,6 +135,10 @@ void
)
{
Check(this);
static const int sPerf = getenv("BT_PERF_LOG") ? 1 : 0;
LARGE_INTEGER t0, t1, fq;
++gBTSegWCalls;
if (sPerf) QueryPerformanceCounter(&t0);
JointSubsystem *joints = GetJointSubsystem();
Check(joints);
@@ -135,6 +149,7 @@ void
//
if (joints->AreJointsModified())
{
++gBTSegWDirty;
EntitySegment::SegmentTableIterator iterator(segmentTable);
EntitySegment *current_segment;
while( (current_segment = iterator.ReadAndNext() ) != NULL)
@@ -153,6 +168,12 @@ void
my_segment.GetSegmentToEntity(),
localToWorld
);
if (sPerf)
{
QueryPerformanceCounter(&t1);
QueryPerformanceFrequency(&fq);
gBTSegWMs += 1000.0 * (double)(t1.QuadPart - t0.QuadPart) / (double)fq.QuadPart;
}
Check_Fpu();
}
engine/MUNGA_L4/L4VIDEO.cpp
+14
View File
@@ -9034,6 +9034,20 @@ void DPLRenderer::ExecuteImplementation(RendererComplexity, RendererOrigin::Inte
DEBUG_STREAM << "[rstat] frames=" << sFrames << " avg=" << (sAcc / sFrames)
<< "ms maxDraw=" << sMaxD << " maxPresent=" << sMaxP
<< " batches=" << gNumBatches << " culled=" << gBTNumCulled << "\n" << std::flush;
// #149: segment-refresh telemetry on the same cadence (BT_PERF_LOG).
// calls = GetSegmentToWorld entries; dirty = the mark-every-segment
// invalidation passes (the expensive arm the #141 sweep may have
// multiplied); ms = time inside the accessor for the whole window.
{
static const int sSegPerf = getenv("BT_PERF_LOG") ? 1 : 0;
extern int gBTSegWCalls, gBTSegWDirty;
extern double gBTSegWMs;
if (sSegPerf)
DEBUG_STREAM << "[segperf] calls=" << gBTSegWCalls
<< " dirty=" << gBTSegWDirty
<< " ms=" << gBTSegWMs << "\n" << std::flush;
gBTSegWCalls = 0; gBTSegWDirty = 0; gBTSegWMs = 0.0;
}
sAcc = 0.0; sFrames = 0; sMaxD = 0.0; sMaxP = 0.0;
}
}
game/reconstructed/mech4.cpp
+13 -1
View File
@@ -9031,8 +9031,20 @@ void
// This is the BEAM muzzle -- the same stale-cache exposure the
// missile launch had, so a peer's beam would also originate
// from the bind-pose gun port instead of the twisted torso.
// #149 A/B (BT_BEAM_SEGFRESH=0): revert THIS site to the
// pre-sweep plain compose, to measure whether the per-beam
// per-frame dirty-pass is the 857 draw-stall regression.
// This site runs inside the DRAW path per emitter per frame;
// the other swept sites are per-salvo/per-hit and cannot be
// a per-frame cost. Default = fresh (the swept behaviour).
static const int sBeamFresh =
!(getenv("BT_BEAM_SEGFRESH") && *getenv("BT_BEAM_SEGFRESH") == '0');
LinearMatrix mw;
GetSegmentToWorld(*s_portCache[energyOrdinal], &mw);
if (sBeamFresh)
GetSegmentToWorld(*s_portCache[energyOrdinal], &mw);
else
mw.Multiply(s_portCache[energyOrdinal]->GetSegmentToEntity(),
localToWorld);
mz = mw; // Point3D = matrix translation
}
}
scratchpad/night14/segperf.sh
+74
View File
@@ -0,0 +1,74 @@
#!/usr/bin/env bash
# =========================================================================
# #149 -- 817 -> 857 stall regression (Oracle: 97 blocks >50ms, all in the
# mission-load window, maxDraw up to 518ms; zero such blocks on 817, same
# machine). My filed suspect was the #141 segment-cache sweep -- but that is
# a HYPOTHESIS, and #137 just taught us what plausible-but-unmeasured
# theories are worth. So: measure first.
#
# INSTRUMENTATION (this build):
# [segperf] calls=<GetSegmentToWorld entries> dirty=<mark-every-segment
# invalidation passes> ms=<time inside the accessor> -- per rstat window,
# BT_PERF_LOG-gated. The DIRTY count is the tell: if the beam path
# multiplies invalidations, dirty >> mechs-per-frame and ms tracks maxDraw.
#
# A/B: identical 2-node runs, beams firing continuously.
# run A: default (swept behaviour: beam muzzle via GetSegmentToWorld)
# run B: BT_BEAM_SEGFRESH=0 (pre-sweep plain compose at the BEAM site only)
# If A's stalls/dirty collapse in B, the beam-site sweep is the regression.
# If A == B and both are clean, the suspect is EXONERATED and the real 857
# load-stall cause is elsewhere (next: diff the load path).
# =========================================================================
set -x
. /c/git/bt411/scratchpad/night6/bench_common.sh
cd /c/git/bt411/content || exit 1
run_one () { # $1 = tag, $2 = extra env value for BT_BEAM_SEGFRESH
taskkill //F //IM btl4.exe > /dev/null 2>&1
sleep 2
rm -f sp_${1}_a.log sp_${1}_b.log sp_${1}_relay.log
bt_expert_egg MP.EGG SP.EGG
sed -i "s/^map=.*/map=grass/; s/^time=.*/time=day/; s/^vehicle=.*/vehicle=madcat/" SP.EGG
( export BT_GOTO=enemy BT_GOTO_STOP=120 BT_AUTOFIRE=1 BT_AF_PERIOD=3
export BT_MP_LOG=1
bt_launch sp_${1}_b.log SP.EGG 0x0C -net 1601 )
sleep 2
( export BT_GOTO=enemy BT_GOTO_STOP=120 BT_AUTOFIRE=1 BT_AF_PERIOD=3
export BT_PERF_LOG=1 BT_MP_LOG=1
export BT_BEAM_SEGFRESH=${2}
bt_launch sp_${1}_a.log SP.EGG 0x03 -net 1501 )
sleep 5
python ../tools/btconsole.py SP.EGG 127.0.0.1:1501 127.0.0.1:1601 > sp_${1}_relay.log 2>&1 &
local RELAY=$!
sleep 260
kill $RELAY 2>/dev/null
sleep 3
bt_kill_ours; sleep 2; taskkill //F //IM btl4.exe > /dev/null 2>&1; sleep 3
}
run_one fresh 1
run_one legacy 0
echo "=================== #149 SEGPERF A/B ==================="
for t in fresh legacy; do
echo "--- $t ---"
python - <<PY
import re, io
v=[]; seg=[]
for ln in io.open(r"C:\git\bt411\content\sp_${t}_a.log", encoding="latin-1", errors="replace"):
m=re.search(r"\[rstat\] frames=\d+ avg=([\d.]+)ms maxDraw=([\d.]+)", ln)
if m: v.append((float(m.group(1)), float(m.group(2))))
m=re.search(r"\[segperf\] calls=(\d+) dirty=(\d+) ms=([\d.]+)", ln)
if m: seg.append((int(m.group(1)), int(m.group(2)), float(m.group(3))))
if v:
import statistics
avgs=[a for a,_ in v]; draws=[d for _,d in v]
stall=sum(1 for a,_ in v if a>50)
print(" rstat blocks=%d avg-med=%.2fms maxDraw-med=%.2f maxDraw-worst=%.1f blocks>50ms=%d"
% (len(v), statistics.median(avgs), statistics.median(draws), max(draws), stall))
if seg:
c=[x[0] for x in seg]; d=[x[1] for x in seg]; ms=[x[2] for x in seg]
print(" segperf windows=%d calls-med=%d dirty-med=%d ms-med=%.2f ms-worst=%.2f"
% (len(seg), sorted(c)[len(c)//2], sorted(d)[len(d)//2], sorted(ms)[len(ms)//2], max(ms)))
PY
done