Files
BT411/scratchpad/night14/segperf.sh
T
Joe DiPrimaandClaude Opus 5 a77c5a1407 #149: measure the filed suspect -- the #141 segment sweep is EXONERATED; ship [segperf] telemetry
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
2026-08-09 16:46:10 -05:00

75 lines
3.3 KiB
Bash

#!/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