This repository has been archived on 2026-09-16. You can view files and clone it. You cannot open issues or pull requests or push a commit.
Files
Syplheed-Reborn/tools/re-capture/wave7_probe.py
Sylpheed RE agent 14385ae170 re: clean run reproduces; startup was eating a third of the window
Second consecutive run with no stall flag on any sample, which confirms that
disabling the periodic rescan is what fixed the freezes. Nine losses, four
flicker increases all correctly rejected, and zero confirmed arrivals. The
trustworthy negative now extends to 240 s of verified-live flight, roughly 132
game-seconds, so nothing arrives past the route table's t=90 or t=120 entries
either.

The flicker rate is worth noting: about one spurious increase per minute. That
is the rate at which the old rule would have been manufacturing arrivals.

The arithmetic of the run exposed a waste. Boot finished at 249 s, the probe ran
240 s, and the turn's 595 s cap fired, leaving about 100 s unaccounted for
between them -- the witness calibration and the initial craft enumeration.

enumerate_craft was iterating every 4-byte word of 32 MB in Python, eight
million steps, to find fourteen fixed needles. Replaced with bytes.find() per
definition VA, which is the same search at C speed and is what the vtable scan
already did. Not yet run.

If that recovers most of the hundred seconds the observation window grows from
about 240 s to about 340 s, roughly 187 game-seconds, which would finally reach
the t=170 route entry -- the first of the schedule's later arrivals that no run
has yet been able to observe.
2026-08-24 18:31:51 +00:00

207 lines
10 KiB
Python
Executable File

#!/usr/bin/env python3
"""Cheap per-record watch: the heavy rescan was stalling the guest.
A no-probe control ran 300 s clean while probed runs stalled at 27-255 s
(guest-stalls.md), so the 32 MB rescan every 12 s has to go. After one full
enumeration the craft bases and their roster links are known, and a sample only
needs the hull word at each base -- about 1.2 KB instead of 32 MB. A full rescan
runs only every RESCAN seconds to catch anything genuinely new.
"""
import os, sys, time, struct, collections, importlib.util
SD = __file__.rsplit('/', 1)[0]
sys.path.insert(0, SD)
import gmem, gworld, entities2
_w3 = importlib.util.spec_from_file_location('w3', SD + '/wave3_probe.py')
wave3 = importlib.util.module_from_spec(_w3); _w3.loader.exec_module(wave3)
ROSTER_VT = struct.pack('>I', 0x820AF030)
DELTA, WIN, LINK, HULL = 0x130, 0x400, 0x08, 0x154
BASELINE = 116
# Periodic rescan DISABLED. It was a 32 MB read every 90-180 s, the only
# recurring heavy cost left, and it exists to catch craft that appear from
# nowhere -- which the roster work already showed does not happen: every
# participant is allocated at mission load, so an arrival is a state change on
# an existing craft, not a new allocation. Set >0 to re-enable.
RESCAN = 0
def scan_vt(fd, size, vt):
out = []
for a, b in gmem.extents(fd, size):
pos = a
while pos < b:
m = min(1 << 24, b - pos)
blob = os.pread(fd, m, pos)
i = blob.find(vt)
while i != -1:
if (pos + i) % 4 == 0: out.append(pos + i)
i = blob.find(vt, i + 1)
pos += m
return sorted(out)
def enumerate_craft(fd, defs, want):
"""Full heap scan. Returns [(base, unit, roster_off)].
Was iterating every 4-byte word of 32 MB in Python -- 8 million steps -- and
the startup cost worked out at roughly 100 s of wall-clock, which is a third
of the observation window a turn can afford. Each definition VA is a fixed
4-byte needle, so bytes.find() does the same search at C speed.
"""
lo, hi = gmem.va_to_off(entities2.ENT_VA_LO), gmem.va_to_off(entities2.ENT_VA_HI)
out, pos = [], lo
while pos < hi:
m = min(1 << 24, hi - pos)
blob = os.pread(fd, m, pos)
for needle, nm in defs.items():
i = blob.find(needle)
while i != -1:
if (pos + i) % 4 == 0:
base = pos + i - DELTA
head = os.pread(fd, WIN, base)
own = None
for j in range(0, len(head) - 3, 4):
(p,) = struct.unpack_from('>I', head, j)
if p in want: own = want[p]; break
out.append((base, nm, own))
i = blob.find(needle, i + 1)
pos += m
return sorted(out)
def alive(fd, base):
try: return struct.unpack('>f', os.pread(fd, 4, base + HULL))[0] > 0
except Exception: return False
def main():
secs = int(sys.argv[1]) if len(sys.argv) > 1 else 300
every = int(sys.argv[2]) if len(sys.argv) > 2 else 15
w = gworld.World(); fd = w.fd
defs = entities2.definitions(w)
if not defs: print('NOT IN A MISSION'); return 2
# The 42-instead-of-116 anomaly has now happened twice. Rather than discard
# immediately, rescan a few times: if the count CLIMBS toward 116 the roster
# is being built progressively and the probe simply started too early, which
# is a fact worth having. If it sits at 42 it is something else.
roster = scan_vt(fd, w.size, ROSTER_VT)
print('roster records: %d (baseline %d)' % (len(roster), BASELINE))
for attempt in range(1, 6):
if len(roster) == BASELINE: break
time.sleep(10)
roster = scan_vt(fd, w.size, ROSTER_VT)
print(' rescan %d: %d records' % (attempt, len(roster)), flush=True)
if len(roster) != BASELINE:
print('DISCARD: settled at %d, not the reproduced baseline %d'
% (len(roster), BASELINE)); return 3
f = os.fdopen(os.dup(fd), 'rb')
label, want = {}, {}
for o in roster:
va = gmem.primary_va(o)
if va is None: continue
label[o] = wave3.resolve_id(f, w.size, o)[0] or '?'
want[va + LINK] = o
# A 1 MB window was too narrow and found nothing, yet the summary still
# printed "stalled samples=0" -- a witness that does not exist cannot report
# zero stalls, and that is false reassurance, not a clean run. Search wider,
# and if there is still no witness say the run is UNVALIDATED.
# Taking the FIRST word that advances was wrong: it flagged 13 samples as
# stalled in a run that was recording losses in those same samples, which a
# frozen guest cannot do. Some counters simply advance intermittently. Use
# timer_probe's approach instead -- collect every candidate, keep the modal
# rate cluster, and call a stall only when a MAJORITY of that cluster fails
# to advance.
# 4 MB was too narrow: it yielded 5 candidates at a nominal 24/s that then
# failed to advance in 15 s windows where craft were being destroyed, i.e.
# they are bursty, not frame counters. timer_probe searched the WHOLE 32 MB
# region and found 286 with a clean cluster at ~17/s. Pay the one-off cost.
# REVERTED to the full-region calibration. Trimming it to 8 spread 512 KB
# windows to save I/O found only 17 candidates, none of them frame counters,
# and the witness then reported 0/17 stalled on EVERY sample of a run that
# recorded 13 losses -- a total contradiction. The frame-rate cluster is
# sparse and spread sampling misses it. Two 32 MB reads once at startup is
# the price of a witness that works; the recurring cost was the periodic
# rescan, and that is what has been cut instead.
lo, hiw = gmem.va_to_off(0xBC000000), gmem.va_to_off(0xBE000000)
def grab():
out, pos = bytearray(), lo
while pos < hiw:
n = min(1 << 24, hiw - pos); out += os.pread(fd, n, pos); pos += n
return bytes(out)
a = grab(); time.sleep(3.0); b = grab()
cands = []
for k in range(0, min(len(a), len(b)) - 3, 4):
va, vb = struct.unpack_from('>I', a, k)[0], struct.unpack_from('>I', b, k)[0]
if va < vb and 5 < (vb - va) / 3.0 < 200:
cands.append((lo + k, round((vb - va) / 3.0)))
# The MODAL cluster is not the frame counter. One run picked a modal rate of
# 93/s, and only 11 of 31 of those advanced during active combat -- they are
# subsystem counters that tick in bursts. timer_probe measured the frame-rate
# cluster at ~17/s, matching Canary's 14-19 fps on this box, so prefer a
# cluster in that band and fall back to modal only if none exists.
rates = collections.Counter(r for _, r in cands)
band = [r for r in rates if 8 <= r <= 40]
pick = max(band, key=lambda r: rates[r]) if band else (
rates.most_common(1)[0][0] if rates else None)
ticks = [o for o, r in cands if r == pick][:32]
if len(ticks) < 8:
print('WARNING: only %d witnesses; stall detection is weak' % len(ticks))
print('tick witnesses: %d candidates, using %d at %s/s (frame-rate band)'
% (len(cands), len(ticks), pick)
if ticks else 'tick witnesses: NONE -- RUN UNVALIDATED')
last_ticks = [struct.unpack('>I', os.pread(fd, 4, o))[0] for o in ticks]
craft = enumerate_craft(fd, defs, want)
print('craft %d, linked %d' % (len(craft), sum(1 for c in craft if c[2])))
prev = collections.Counter(c[2] for c in craft if c[2] and alive(fd, c[0]))
print('t= 0s deployed=%d strengths %s'
% (len(prev), sorted(collections.Counter(prev.values()).items())), flush=True)
t0 = time.time(); last_rescan = t0; arr = los = 0; stalls = 0
pending, confirmed = {}, 0
while time.time() - t0 < secs:
time.sleep(every)
el = round(time.time() - t0)
if RESCAN and time.time() - last_rescan > RESCAN:
craft = enumerate_craft(fd, defs, want); last_rescan = time.time()
cur = collections.Counter(c[2] for c in craft if c[2] and alive(fd, c[0]))
st = ''
if ticks:
now = [struct.unpack('>I', os.pread(fd, 4, o))[0] for o in ticks]
moved = sum(1 for x, y in zip(last_ticks, now) if y > x)
# "Fewer than half" was too strict: 11 of 31 advanced while craft
# were being destroyed. The unambiguous signal in that run was
# 0 of 31, which coincided exactly with losses stopping.
if moved == 0:
st = ' *** GUEST STALLED (%d/%d witnesses moved) ***' % (moved, len(ticks))
stalls += 1
last_ticks = now
# Report EVERY increase, not just 0 -> n. The first run logged a record
# reading 13 then 14 with no event printed, which is how flicker in the
# hull-based liveness read hides: only decreases were being surfaced, so
# a spurious 0 -> 2 looked like an arrival while 13 -> 14 looked like
# nothing. An arrival must also PERSIST to count.
a_ = [(o, prev.get(o, 0), cur[o]) for o in cur if cur[o] > prev.get(o, 0)]
l_ = [(o, prev[o], cur.get(o, 0)) for o in prev if cur.get(o, 0) < prev[o]]
for o, x, y in a_:
if x == 0: pending[o] = pending.get(o, 0) + 1
for o in list(pending):
if cur.get(o, 0) == 0: pending.pop(o, None) # vanished: flicker
elif pending[o] == 2:
confirmed += 1
print(' *** CONFIRMED ARRIVAL %-26s now %d (persisted 2 samples)'
% (label.get(o, '?'), cur[o]), flush=True)
pending[o] = 3
arr += sum(1 for x in a_ if x[1] == 0); los += len(l_)
print('t=%4ds deployed=%d up=%d down=%d (cum up %d / down %d, confirmed %d)%s'
% (el, len(cur), len(a_), len(l_), arr, los, confirmed, st), flush=True)
for o, x, y in a_:
print(' up %-30s %d -> %d%s' % (label.get(o, '?'), x, y,
' <- candidate arrival' if x == 0 else ''), flush=True)
for o, x, y in l_: print(' loss %-30s %d -> %d' % (label.get(o, '?'), x, y), flush=True)
prev = cur
if not ticks:
print('\nRUN UNVALIDATED: no tick witness, so flat samples prove nothing.')
print('\nTOTAL candidate-up=%d down=%d CONFIRMED arrivals=%d stalled samples=%s'
% (arr, los, confirmed, stalls if ticks else 'UNKNOWN'))
return 0
if __name__ == '__main__':
sys.exit(main())