diff --git a/docs/dev/GE-ENV-PROBES.md b/docs/dev/GE-ENV-PROBES.md index 718695ef..dd2b1aac 100644 --- a/docs/dev/GE-ENV-PROBES.md +++ b/docs/dev/GE-ENV-PROBES.md @@ -42,6 +42,7 @@ Two classes: | `GE_WRAPFIX` | `port/fast3d/gfx_pc.cpp:3166` (`gfx_set_wrap_fix`) | RC3 test override for the `Video.WrapFix` D74/D167 wrap-block path (`atoi != 0` wins over the ini). | **live** (RC3 not finished) | | `GE_SAVELOG` | `src/game/file.c:46`, `src/game/file2.c:16` (`SAVELOG` macro), `src/boss.c:749`, `src/game/objective_status.c:297,343` | Traces the campaign save/unlock chain (objective completion → `end_of_mission_briefing` → `fileWriteSave` → EEPROM). Used to confirm D157. `g_savelogObjOnce` gates the per-criterion dump to the `bossReturnTitleStage` call. | **live** (strip once a few more level boundaries are playtested) | | `GE_D160` | `src/boss.c:744`, `src/game/bondview2.c:791`, `src/aicommands.def:10055,10181,10236,10242,10247` (all `#ifdef PORT`) | Dam exit-cutscene (D148/D160) diagnostic: trace points in `bossReturnTitleStage`, `bondviewSetCameraMode`, and AI cmds `EndLevel`/`exit_level`/`CameraLookAtBondFromPad`/`CameraSwitch`. **Investigation in progress** — user owes a `GE_D160=1` Dam run. | **live** | +| `GE_D193` | `src/game/frametiming.c` (`waitForNextFrame`, `#ifdef PORT`) | Per-wall-second line: `render=` rendered frames, `sim=` sim ticks delivered (Σ of the `deltaFrames`/`g_ClockTimer` fed downstream), `clamped=` frames whose catch-up hit `FRAMETIMING_PORT_MAX_CATCHUP`, `maxraw=` largest pre-clamp delta. Healthy steady state = `render=30 sim=60 clamped=0 maxraw=2` (measured M-80, all levels idle). Use to check whether the wall-clock timer under-advances under real AI load (D193). Cheap; safe for a full playtest. | **live** (D193) | | `GE_DTEX` | `port/fast3d/gfx_pc.cpp:1001` | Per-`import_texture` param log (dims / line / size / lod / gen_mipmaps). Used to root-cause RC2 and D159. Kept as an inert diagnostic. | **live** (RC2/RC3 not finished) | | `GE_TEXDUMP` | `port/fast3d/gfx_pc.cpp:1020`, `port/fast3d/gfx_opengl.cpp:700` | PPM dump of every uploaded texture + a `fmt/siz/palfmt/palidx/pal[0..3]` line. Root-caused D161 (Depot ceiling). Kept as an inert diagnostic. | **live** (RC3 not finished) | | `GE_D116` | `port/fast3d/gfx_pc.cpp:1710,2362`, `src/game/textrelated.c:265,541` (cached `ge_d116`) | HUD/text "X-mirror" (D114/D116) vbo/uv trace. **D114/D116 CLOSED — NOT A BUG (M-33/D168): the captures were upside-down, not mirrored.** Probe is now dead scaffolding — strip on the next cleanup pass. | dead (D114/D116 closed) | diff --git a/docs/dev/findings.md b/docs/dev/findings.md index 74927fa1..8962fa9e 100644 --- a/docs/dev/findings.md +++ b/docs/dev/findings.md @@ -392,7 +392,7 @@ covers D24–D69; the log continues in §H (D32 procedure, D70–D121). | D189 | **Linux `-fstack-protector` aborts on the decomp's latent stack-buffer overruns (M-48) — FIXED.** Two hit on `-level_09`: (1) `sub_GAME_7F0B1DDC` (`stan.c`) — local `StandTile *tileStack[39]`, bail check `if (cat >= 41)` runs only once per outer iteration so `cat` reaches `40 + pointCount` and the append writes past the end; BUNKER1 prop room-list setup legitimately visits ~40 tiles (confirmed in GDB: 30 valid distinct tile ptrs and climbing; `standTileStart=0x701ae160`, so **not** a pointer-truncation bug — the earlier "blob >4 GiB" triage premise was wrong). (2) `bondviewCalcIntroSwirlCamera` (`bondview2.c`) — `f32 pointbuf[10]` written `[-3 .. 11]` via `&pointbuf[i*3]`, i∈[-1..2]. Both harmless on N64 + the MinGW build (no stack protector); only Ubuntu gcc's `-fstack-protector-strong` default makes them fatal `__stack_chk_fail`. **Fix:** `-fno-stack-protector` globally (`CMakeLists.txt`) to match the N64/MinGW builds, + `tileStack[64]` under `#ifdef PORT` for the one cleanly-bounded case, + `stan.c:2225` link-resolve moved to the D177 `PORT_PTRADD` macro for consistency. A *hardened* Linux build would need the whole overrun class swept. **Verified:** Windows `-level_09` framediff 3/3; Linux `-O2` `-level_09` runs to frame 2100+ no crash. porting-notes.md §C. | FIXED (`CMakeLists.txt`, `src/game/stan.c` `#ifdef PORT`); PR #23 | | D190 | **Linux `-level_45` SIGSEGV at load in `add_ptr_to_objective` (`objective.c:64`) (M-48, open).** `objective_ptrs[objective->menu] = objective;` faults — `objective` wild or `objective->menu` a garbage index → OOB write. Almost certainly the D122/D126/D132 propDef-stride / ROM-serialized-struct-widening family (`struct objective_entry` / the type-23/type-1E setup-text record chain read at the wrong stride on PC). Found in the M-48 Linux level sweep: **5/6 spot-checked levels (`-level_09/20/27/34/37`) load + render fine; `-level_45` is the one failure.** Not a v0.1.0-alpha blocker (alpha is explicitly "expect crashes"). Windows: `-level_45` load status not re-checked this session. | OPEN — not investigated (M-48) | | D191 | **Windows `-O2` release-bundle crash: SIGSEGV in `modelGetNodeRwData` (`src/game/model.c:478`) — the `root->Parent` node-tree walk (M-49, user playtests of the v0.1.0 win64 bundle).** **Two instances, identical fault PC `0x1400801b1`:** (1) fresh save, killed the first guard right after escaping the cell in Bunker ii; (2) Statue (`-level_49`?), right after the Trevelyan meeting cutscene. `ge007.crash.log` (auto-dump; symbols intact in the shipped exe, `addr2line` resolves): PC = `modelGetNodeRwData` at `model.c:478` — the `switch (root->Opcode & 0xff)`, i.e. `root` (a `ModelNode *`) is bad; `addr2line` puts it in the inlined self-recursion at `:532`, so the `while (root->Parent) { root = root->Parent; … }` walk (`model.c:527-540`) handed a garbage node into the recursive call. Instance 1: `Rdx = 0x70267bc000000000` — a `~0x70266xxx` heap address in the **high 32 bits, zero low half** = 32-bit pointer field read as 64-bit (or a byte-swapped `u32` pair). Instance 2: `Rdx = 0`, FAULT ADDR `0x0` — `root` (or `root->Parent`) resolved to NULL. Both: `Rcx=Rdi` = the `~0x7008xxxx`/`~0x7007xxxx` object ptr, `R8 = 0x1d` (29). So the `Parent` chain in some model contains a **truncated or NULL link** — pointer-width / byte-swap family (D3x, D119 `weapons_held[]->chr` type-pun, D122/D126/D132 propDef-stride). NOT weapon-fire-specific — common factor is `modelGetNodeRwData` running on a character/cutscene model whose node tree has a bad `Parent`. Crash logs saved: `scratchpad/crashlogs/`. **Repro aid:** shipped exe has full symbols; `debug-crash.ps1` in the bundle dir runs it under gdb, `GE_D51=1` → `d52rw.log` rwdata-pool trace. The crash.c EBP backtrace breaks immediately (`#01: 0x1d`) — need a real `bt` + `p *root` + `p *Objinst` at the fault. Not yet reproduced under a debugger; no fix. | FIXED + PLAYTEST-VERIFIED (M-79). User replayed Bunker ii (first-guard kill) and Statue (post-Trevelyan cutscene) on the fix build — **both no longer crash** → 21/21 solo levels crash-free (v0.2.0 gate met; Cradle's remaining issue is D193, not a crash). Build clean; bunker1 golden framediff 3/3. **Real gdb backtrace (M-79):** the fault is NOT in the `root->Parent` walk — `root` arrives *already* garbage (`0x70267a9000000000` = a half-word-swapped `u32` `0x70267a90`) from frame #1 `bondviewSelectCuff(model=0x70076808, header=0x700763a0, switchindex=29)`, called from `gunUpdateAndFire(GUNRIGHT)` on the frame the player fires. `bondviewSelectCuff` byte-indexes `header->Switches` (a `ModelNode *` array — **8-byte stride on PC**, widened per D43/D45) with `offset = switchindex << 2` (N64 4-byte stride), so every `base[N]` deref lands mid-slot and yields a misaligned half-pointer that is non-NULL by luck → `modelGetNodeRwData(root=garbage)`. **Exactly the D140 bug class** — D140 fixed the identical pattern in `gunfire.c:1740`; this call site was missed. Fix: PORT-only `offset = switchindex * (s32) sizeof(ModelNode *)`; the `base = (u8*)switches + offset` math and the `#else` N64 line are unchanged. ABI/pointer-width only (D3x class), no game-logic change. The Statue instance (`Rdx=0`, NULL fault addr) is the same site landing on a slot whose bytes read as 0. | -| D193 | **NPC AI locomotion is too slow — characters don't move to their destinations at the original game's rate (M-49, user playtest; clarified after the FULL 21-level playthrough — "the biggest overall flaw").** Not (primarily) an animation-playback bug — the *travel speed* of scripted/AI movement is wrong: guards, named NPCs (Trevelyan, Ourumov) and friendlies (Natalya) all take noticeably longer to run/walk to their goal positions than on N64. General, not chr-specific. **Leading hypothesis — the D117/D134/D155/D156 wall-clock-timing family:** `chr.c` / `chrai.c` integrate movement as `pos += speed * g_GlobalTimerDelta` and step sim loops `while (i < g_ClockTimer)` / `-= g_ClockTimer` (`chr.c:1437,1446,1491-1502,1862,2359,2569`; `chrai.c:76`). On the port `osGetCount()` is free-running wall-clock (D117), `g_GlobalTimerDelta`/`g_ClockTimer` are derived from it, and D155's `FRAMETIMING_PORT_MAX_CATCHUP = 6` clamps `nextFrameTime`. If the effective per-second sum of `g_GlobalTimerDelta` (or the `g_ClockTimer` tick count) runs low — quantization, the catch-up clamp biting during normal play, or a units mismatch (`g_JP_GlobalTimerDelta` vs `g_GlobalTimerDelta`, `chr.c:1435/1437`) — every delta-scaled AI motion integrates slow while **player** movement (input-driven per frame) still feels right, which is exactly the reported split. Related: **D170** (Ourumov/Trevelyan "flee" looks wrong — flagged there as possibly the same locomotion-speed issue rather than an AI divergence). Also possible: `chrGoToBond/Chr(SPEED_RUN/WALK/SPRINT)` speed enum → path-follow step, or pathfinding advancing ≤1 waypoint per frame-quantized tick. **Instances seen (M-49 full playthrough):** (a) Facility — the post-scripted-scene beat with Ourumov + the soldier squad: the soldiers **walk in super slowly and take a long time to path into firing positions** before they start shooting (this is regular squad combat AI, not a named-NPC script — good evidence the slowdown is general delta-scaled `chr` locomotion / path-following, not one ailist); (b) the named-NPC flee behaviour on Silo (Ourumov) and Cradle (Trevelyan) — see D170; (c) **Natalya (the escort NPC) always walks really slow** — on every escort level (Bunker ii, Statue, Control, Archives) she trails far behind, forcing the player to wait. Escort follow-AI is the same `chrGoToChr`/path-follow path as (a). **WORST CASE — Cradle (`-level_51`) is "bugged out completely" due to Trevelyan's behaviour (M-49).** The final level is Trevelyan-fleeing-and-scripted end to end (he runs the antenna cradle, climbs, drops to the cradle floor, the helicopter beat); if his locomotion timing / path-following is off he never hits the trigger points and the level's scripted progression stalls or goes haywire. This makes D193 effectively a **can't-properly-finish-the-game** bug, not just cosmetic sluggishness. **Next:** log `g_GlobalTimerDelta` + `g_ClockTimer` per frame during normal play and check the 1-second sum vs the N64's ~60; time a guard's run across a known distance vs reference footage; then watch Trevelyan's chr state / current AI command on Cradle. | OPEN — root-cause hypothesis (timing family), not investigated (M-49). **Highest-impact playtest finding — breaks Cradle.** | +| D193 | **NPC AI locomotion is too slow — characters don't move to their destinations at the original game's rate (M-49, user playtest; clarified after the FULL 21-level playthrough — "the biggest overall flaw").** Not (primarily) an animation-playback bug — the *travel speed* of scripted/AI movement is wrong: guards, named NPCs (Trevelyan, Ourumov) and friendlies (Natalya) all take noticeably longer to run/walk to their goal positions than on N64. General, not chr-specific. **Leading hypothesis — the D117/D134/D155/D156 wall-clock-timing family:** `chr.c` / `chrai.c` integrate movement as `pos += speed * g_GlobalTimerDelta` and step sim loops `while (i < g_ClockTimer)` / `-= g_ClockTimer` (`chr.c:1437,1446,1491-1502,1862,2359,2569`; `chrai.c:76`). On the port `osGetCount()` is free-running wall-clock (D117), `g_GlobalTimerDelta`/`g_ClockTimer` are derived from it, and D155's `FRAMETIMING_PORT_MAX_CATCHUP = 6` clamps `nextFrameTime`. If the effective per-second sum of `g_GlobalTimerDelta` (or the `g_ClockTimer` tick count) runs low — quantization, the catch-up clamp biting during normal play, or a units mismatch (`g_JP_GlobalTimerDelta` vs `g_GlobalTimerDelta`, `chr.c:1435/1437`) — every delta-scaled AI motion integrates slow while **player** movement (input-driven per frame) still feels right, which is exactly the reported split. Related: **D170** (Ourumov/Trevelyan "flee" looks wrong — flagged there as possibly the same locomotion-speed issue rather than an AI divergence). Also possible: `chrGoToBond/Chr(SPEED_RUN/WALK/SPRINT)` speed enum → path-follow step, or pathfinding advancing ≤1 waypoint per frame-quantized tick. **Instances seen (M-49 full playthrough):** (a) Facility — the post-scripted-scene beat with Ourumov + the soldier squad: the soldiers **walk in super slowly and take a long time to path into firing positions** before they start shooting (this is regular squad combat AI, not a named-NPC script — good evidence the slowdown is general delta-scaled `chr` locomotion / path-following, not one ailist); (b) the named-NPC flee behaviour on Silo (Ourumov) and Cradle (Trevelyan) — see D170; (c) **Natalya (the escort NPC) always walks really slow** — on every escort level (Bunker ii, Statue, Control, Archives) she trails far behind, forcing the player to wait. Escort follow-AI is the same `chrGoToChr`/path-follow path as (a). **WORST CASE — Cradle (`-level_51`) is "bugged out completely" due to Trevelyan's behaviour (M-49).** The final level is Trevelyan-fleeing-and-scripted end to end (he runs the antenna cradle, climbs, drops to the cradle floor, the helicopter beat); if his locomotion timing / path-following is off he never hits the trigger points and the level's scripted progression stalls or goes haywire. This makes D193 effectively a **can't-properly-finish-the-game** bug, not just cosmetic sluggishness. **Next:** log `g_GlobalTimerDelta` + `g_ClockTimer` per frame during normal play and check the 1-second sum vs the N64's ~60; time a guard's run across a known distance vs reference footage; then watch Trevelyan's chr state / current AI command on Cradle. | OPEN — **steady-state timing keystone MEASURED and the "sim sums low" hypothesis is CONTRADICTED (M-80).** Added a `GE_D193=1` per-wall-second probe in `waitForNextFrame()` (`src/game/frametiming.c`, `#ifdef PORT`, env-gated): logs render frames, sim ticks delivered (= sum of the `deltaFrames` fed to `updateFrameCounters` = sum of `g_ClockTimer`), catch-up clamp hits, and max raw pre-clamp delta. Built ntsc-final, ran `-level_09 / _20 / _27 / _34` idle-after-load, ~20 s each. **Every level, rock-steady: render = 30.0 fps, sim = 60.0 ticks/s, clamped = 0, maxraw = 2.** i.e. each rendered frame carries `g_ClockTimer = 2` and the per-second sum is *exactly* the N64's ~60 — the wall-clock timer is NOT running low in steady state, and `FRAMETIMING_PORT_MAX_CATCHUP` never bites in normal play. VSync on/off made no difference (still 30/60). So the B1 premise ("`g_GlobalTimerDelta`/`g_ClockTimer` sum low over a real second") is wrong for the common case; D193 must come from elsewhere. **Residual quantization risk (not yet observed):** `nextFrameTime = (dt_counts + 387937) / 775875` is integer-rounded per frame with no remainder carry, so a scene that renders at a *steady* rate between 30 and 60 that is not an integer divisor of 60 (e.g. a solid 50 fps → dt≈20 ms → rounds to 1 → sim 50/s, ~17 % slow) would under-advance; the fix there is a fractional accumulator in the `#ifdef PORT` path. But the port renders a hard 30 (software RSP ≈ 60 µs/frame — not GPU-bound; the cap is the `pendingGfx < 2` double-buffer + sched round-trip), so this only matters if a real AI-heavy scripted scene drops into the 20–30 band. **Next (needs input, interactive session):** drive Bond into the Facility Ourumov/squad beat (D193a) and Cradle Trevelyan run with `GE_D193=1` — confirm render/sim hold at 30/60 under real AI load; if they do, pivot off timing entirely and instrument a single guard's world position vs. distance/time (anim root-motion rate, `chrGoToChr` SPEED_* enum → step size, path-node spacing) — the travel-speed bug is likely in the locomotion/anim path, not the frame clock. `GE_D193` catalogued in `docs/dev/GE-ENV-PROBES.md`. **Highest-impact playtest finding — breaks Cradle.** | | D194 | **Mouse input needs another tuning pass — RMB aim over-sensitive + sensitivity couples to frame/sim rate (M-49, user playtest).** Two parts. **(a) Aim mode (RMB) is near bang-bang, not proportional** (`port/src/input.c:697-707`): any per-poll delta past `AIM_MOVE_THRESH` emits stick `m = clamp(61 + |Δ|·(MouseAimSpeed/100)·AIM_GAIN, 61, 60+AimBand)` = `[61,80]` — with the M-29 defaults (`MouseAimSpeed=16`, `AIM_GAIN=4.0`, `AimBand=20`) `m` is already 61 (fast) at ~1.5 px/poll and saturates at 80 by ~30 px/poll, so the usable proportional band is tiny and sits near the top of GE's aim range → "way too sensitive," turn rate barely tracks how fast you actually move the mouse. Needs a real response curve (low floor, wider proportional band, maybe a gamma), not a threshold+clamp. **(b) Overall sensitivity correlates with movement/frame rate** (user's words: "correlated with movement speed, does not feel good"): `input.c` emits raw stick counts **per controller poll** with no `g_GlobalTimerDelta` / polls-per-frame normalization (hipfire yaw `sx += edx·(MouseTurnSpeed/100)·6.0` at `:709`; aim as above). GE integrates the stick scaled by its sim delta, and the port's poll cadence vs render/sim cadence drifts with scene load — so effective sensitivity shifts when the framerate does (which reads as "when I'm moving"). Fix direction: accumulate mouse delta and convert to stick using a fixed reference dt (or feed the game a dt-consistent value), so a given hand motion = a given view rotation regardless of fps. Lineage: D118a (hipfire pitch digital vs analog), D165 (menu pointer), D166 (hipfire pitch pulses), D180-B3 (`MouseAimSpeed` 25→16). Config knobs exist (`Input.MouseAimSpeed/AimBand/MouseTurnSpeed/HipfirePitchSpeed`) but the *shape* of the mapping is the problem. | OPEN — root-caused, not fixed (M-49) | | D195 | **Transparency / alpha surfaces broken on Control (M-49, user playtest)** — Natalya's console room, the glass partitions + translucent projected wall displays. Failure mode not yet specified by the reporter (no `GE_PCDUMP` capture taken). Likely a fast3d render-mode / alpha-blend path defect, not a decode one — neighbours D161 (CI8/LUT decode), D172, D176(b) (both blend-adjacent) but those are texture-format bugs, this reads as a blend-state one; check D128 portal adjacency in case the glass geometry is portal-culled wrong instead. Logged in `GRAPHICS-BACKLOG.md`. **Next:** `GE_PCDUMP` capture on Control near the console room, compare RDP render-mode words against N64 `gmain.s` for the glass/display materials. | OPEN — not investigated (M-49), needs a capture | | D197 | **Character face/head textures wrap around the head, seen on Silo (M-49, user playtest).** Reads as `G_TX_CLAMP` not honoured (or a non-power-of-two wrap period) on a head/face texture tile — the texture repeats around the mesh instead of clamping at the UV edge. Not yet isolated to a specific character or texture; no `GE_PCDUMP`/`GE_TEXDUMP` capture taken. Likely fast3d texture-tile setup (clamp/wrap mode bits from the tile descriptor not round-tripped) rather than a data bug, given it's cosmetic and geometry-independent. **Next:** `GE_TEXDUMP` the offending head texture's tile descriptor on Silo, diff clamp/mirror bits against `gmain.s`'s expectations for that material. | OPEN — not investigated (M-49), needs a capture | diff --git a/src/game/frametiming.c b/src/game/frametiming.c index afe0994f..b9a17ed2 100644 --- a/src/game/frametiming.c +++ b/src/game/frametiming.c @@ -2,10 +2,26 @@ #include "frametiming.h" #ifdef PORT +#include +#include /* Max frames of simulation catch-up per rendered frame (D155). 6 ~= 100 ms * at 60 Hz: covers a legitimately slow frame without letting a multi-second * stall spiral the anim/sim loops. */ #define FRAMETIMING_PORT_MAX_CATCHUP 6 + +/* GE_D193=1 — per-second telemetry of the wall-clock timing keystone. + * Prints: render frames this wall-second, sim ticks delivered (sum of the + * deltaFrames fed to updateFrameCounters == sum of g_ClockTimer), how many + * of those frames had their catch-up clamped, and the largest raw + * (pre-clamp) delta seen. A healthy second is ~60 render / ~60 sim / 0 + * clamped. Sim << 60 (or many clamped) is the D193 AI-slowdown mechanism. + * Test-only, env-gated, zero cost unset. */ +static int ft_d193 = -1; +static u32 ft_d193_frames; +static u32 ft_d193_simticks; +static u32 ft_d193_clamped; +static u32 ft_d193_maxraw; +static OSTime ft_d193_wallstart; #endif // data @@ -109,6 +125,26 @@ void waitForNextFrame(void) //maybe WaitForTick * small catch-up bound; after a hitch the sim just resumes at roughly * real-time pace, exactly as the console did when it dropped frames under * load. Timing-compensation class, cf. D117/D134. */ + if (ft_d193 < 0) ft_d193 = getenv("GE_D193") != NULL; + if (ft_d193) { + u32 raw = nextFrameTime; + if (raw > FRAMETIMING_PORT_MAX_CATCHUP) ft_d193_clamped++; + if (raw > ft_d193_maxraw) ft_d193_maxraw = raw; + ft_d193_frames++; + ft_d193_simticks += (raw > FRAMETIMING_PORT_MAX_CATCHUP) + ? FRAMETIMING_PORT_MAX_CATCHUP : raw; + if (ft_d193_wallstart == 0) ft_d193_wallstart = osGetTime(); + OSTime nowus = osGetTime(); + if (nowus - ft_d193_wallstart >= 1000000) { + fprintf(stderr, + "[D193] wall=%.3fs render=%u sim=%u clamped=%u maxraw=%u\n", + (double)(nowus - ft_d193_wallstart) / 1e6, + ft_d193_frames, ft_d193_simticks, ft_d193_clamped, ft_d193_maxraw); + ft_d193_frames = ft_d193_simticks = ft_d193_clamped = ft_d193_maxraw = 0; + ft_d193_wallstart = nowus; + } + } + if (nextFrameTime > FRAMETIMING_PORT_MAX_CATCHUP) { nextFrameTime = FRAMETIMING_PORT_MAX_CATCHUP; }