Skip to content

Add opt-in runtime observability layer (env-gated diagnostics, guest-memory watches, frame recorder)#157

Open
smmathews wants to merge 3 commits into
ran-j:mainfrom
smmathews:feature/10-runtime-observability
Open

Add opt-in runtime observability layer (env-gated diagnostics, guest-memory watches, frame recorder)#157
smmathews wants to merge 3 commits into
ran-j:mainfrom
smmathews:feature/10-runtime-observability

Conversation

@smmathews

@smmathews smmathews commented Jul 7, 2026

Copy link
Copy Markdown
Contributor

Adds an opt-in, bounded runtime observability layer for the PS2 runtime: environment-gated diagnostic probes across the GS/DMA pipeline, guest-memory watches with writer-PC capture, and a frame recorder. Everything is off by default and, with one honestly-documented exception, costs nothing when off.

Problem

Booting a real commercial title (Dragon Quest VIII) against a synthetic-test-clean PS2Recomp checkout exposed a class of bug synthetic tests structurally can't reach: "the game runs, nothing crashes, and the screen is wrong or blank — which of a dozen pipeline stages is silently misbehaving?" Before this layer, the only way to see GS/DMA counters at all was an AGRESSIVE_LOGS build — a special, presumably slower/noisier build a developer has to remember to opt into and rebuild for, rather than something available on demand against the build they're already running. (This surfaced while consuming PS2Recomp as an external library for a real port; previously these counters were visible only in AGRESSIVE_LOGS builds and had to not require a special build.) Concretely, this hit two multi-session debugging problems this layer was built to chase:

  • A title-menu FSM parked at state 201 with no visible symptom. The game booted, drew something, and then nothing further happened on screen. There was no crash, no error, no obviously-wrong register write — just silence. Diagnosing "is the FSM stuck, is rendering stuck, or is presentation stuck" required watching specific guest memory words change (or not) over tens of thousands of frames, correlated with GS pipeline activity, with no facility to do either.
  • Glyph text rendering as solid magenta, then correct-colored-but-invisible. Two independent, stacked bugs (an unsupported GS texture format falling through to a magenta fallback, and a GIFtag nloop double-count silently corrupting a CLUT upload) were indistinguishable from each other and from a dozen other candidate causes without being able to dump what the rasterizer's CLUT-addressing path and the DMA/GIF chain actually saw, per-transfer (both bugs since fixed downstream).

Why it matters

Without this, both bugs above were undiagnosable except by adding throwaway printfs, rebuilding, and discarding them — repeated per hypothesis, with no way to bound the noise (an unthrottled per-primitive or per-store log is unusable at 60 Hz) and no way to leave the instrumentation in place for the next bug. That cost showed up directly: the FSM investigation alone spanned two dated, multi-boot debugging sessions (six instrumented boots) before the root cause (rendering was alive; presentation was the frontier — see [gs:frame-change]/[gs:ad] below) was found. The 1468-line scope here is every one of those throwaway probes turned permanent, bounded, and generic (no DQ8-specific addresses or constants in this PR — those live in the DQ8 runner, not upstream): each probe maps to a specific stage of the pipeline that was, at some point, the prime suspect and had no visibility. Losing any one of them re-opens a debugging session that already took real wall-clock time once. The zero-cost-when-off design (verified via objdump, see below) is what makes it defensible to carry all of them permanently rather than re-deriving a subset per bug.

How the need was found

This wasn't speced up front — each probe was added live, mid-investigation, against a specific symptom, then generalized and kept:

  • ps2_watch guest-memory watches + [gs-activity] summary (originally AGRESSIVE_LOGS-only counters, generalized 2026-07-05): built to answer "did the game start drawing, and is a display framebuffer programmed" without a special build, then extended to answer "which state machine moved, when". Applied directly to the FSM-201 investigation: watches on introState/titleMode/heartbeat-equivalent guest words, in combination with [gs-activity]'s prims=/imgB=/drawFbp= fields, is what separated "the FSM is stuck" from "rendering never started" from "rendering happens but lands in a non-displayed buffer" — the exact three-way ambiguity a bare pixel-count or dma-count couldn't resolve (real ~1,000 prims + ~450k pixel writes/frame landed in fbp 0x0, while the displayed fbp 0x70 only ever received a flat gray clear).
  • [gs:frame-change] and [gs:ad]: added specifically to find why a composite present that was running every frame drew untextured. One instrumented boot with these two new probes (pre-fix vs. post-fix) is what proved GS_REG_PRIM was dropping PRMODECONT state across a bare PRIM write — a generic GS register-semantics bug no synthetic test exercised.
  • [gs:clut-dump], [gs:giftag], [dma:chain]: added while chasing the magenta-glyph bug, to see the exact CLUT-addressing tuple the rasterizer resolved and the raw GIFtag/DMA-chain bytes the guest's own packet writer produced — which is how the GIFtag nloop double-count (an HLE stub bug, not a GS bug) was distinguished from the texture-format bug it was stacked underneath.
  • Frame recorder (PS2X_REC): added to get an objective, comparable artifact for "is the screen actually showing correct content, and is it changing" — replacing eyeballing a live window. It's what turned "the window looks gray" from an impression into a verified milestone: a PS2X_REC-interval capture produced 365 PNGs spanning 289 distinct MD5 hashes, confirming genuinely-changing, recognizable title-sequence art was reaching the displayed buffer.

What this adds

Diagnostics gate (ps2xRuntime/include/runtime/ps2_diag.h, new)

  • A PS2X_DIAG gate cached in an atomic: when off, the hot path pays a single relaxed load.
  • should_log(count, firstN, everyNth) — a first-N-verbose-then-every-Nth throttle shared by every probe, so no site can flood the log.
  • An env_int helper and a test-only override.
  • The new headers are included only by runtime .cpp files; ps2_runtime.h gains just two tiny forward declarations, so nothing enters the recompiled-unit include graph and enabling diagnostics never forces a corpus rebuild.

GS activity headline (ps2_runtime.cpp run loop)

  • A [gs-activity] line summarizing dma/gif/gsw/vif counters, dispfb1/dispfb2/display1, and rasterizer draw stats. Emits once tagged (FIRST ACTIVITY) when any counter first goes nonzero, then at most once per 600 frames and only while counters changed since the last emitted line.
  • The backing GS draw stats (m_statPrims, m_statImageBytes, m_statLastDrawFbp, with accessors) are relaxed atomics updated only inside the ps2_diag::enabled() gate in vertexKick/processImageData. With diagnostics off the draw-dispatch hot path performs no locked read-modify-write — only a predicted-not-taken branch on the cached gate.

GS / DMA pipeline probes (all gated, bounded, register-names-only)

  • [gs:dispenv] in applyGsDispEnv
  • [gs:image] in processImageData — DBP/DPSM/DBW, TRXREG size, byte count (throttled, plus one line on every DBP change)
  • [gs:l2l] in performLocalToLocalTransfer
  • [gs:packed] per-descriptor histogram in writeRegisterPacked
  • [gs:pixels] post-rejection sample in writePixel
  • [gs:frame-change] in vertexKick before drawPrimitive — prim/ctx/FRAME/TEX0/tme/prmodecont on every draw-target FBP change
  • [gs:ad] in the A+D packed case — address + 64-bit data, with an UNKNOWN tag when the address matches no writeRegister case
  • [gs:clut-dump] — one dump per distinct (cbp, cpsm, csa, csm, sourcePsm) CLUT view. Logical indices are resolved through resolveClutIndex, so the CSM1 swizzle fix is applied by construction (CSM2 stays linear). The dump lives in lookupCLUT (rasterizer), where cbp/cpsm/csm/csa are all in scope, and shares the exact index-resolution path used by live texture sampling — the invariant the CSM1 fix protects.
  • [gs:giftag] raw-tag dump in processGIFPacket; [dma:chain] source-chain tag dump with a payload snippet and channel base in ps2_memory.cpp

Guest-memory watches (runtime/ps2_guestwatch.h, new)

  • addWatch(addr, byteWidth, label) / clearWatches() / pollWatches(rdram), polled once per run-loop iteration (~60 Hz). Emits [watch] label 0xaddr: old -> new (change #N), sparsified to every 600th after 16 changes. The poller checks an atomic count and bails before touching rdram or the mutex when nothing is registered.
  • PS2X_WATCH environment hook makes a watch usable in a real run: PS2X_WATCH=ADDR[:SIZE][:LABEL][,…] (ADDR hex or decimal, SIZE default 4) is parsed at boot by armWatchesFromEnv and registers a watch per entry before guest code starts. Arming a watch also enables the diagnostics gate — which turns on the full probe stream (every [gs:*], [dma:*], [watch], … line), exactly as PS2X_DIAG=1 would — so a watch is useful without setting PS2X_DIAG separately. An unset PS2X_WATCH costs nothing.
  • Writer-PC capture: the ps2TraceGuestWrite hook (called by every recompiled store with the CPU context) dispatches — behind a relaxed atomic bool that is false unless a watch is armed — to onGuestWrite, which records the writing PC for overlapping watches; the next [watch] line appends pc=0x…. Guest stores (game thread) and the poller (run-loop thread) both take registryMutex, so writer-PC capture is race-free.

Lifecycle and IO traces: gated [exit] (pc/ra/a0) in the exit() stub, [fioOpen] (ps2 + host path) and [fioRead] (requested vs actual bytes) in the fio syscalls.

Frame recorder (PS2X_REC=1, PS2X_REC_INTERVAL=N): hashes the latched presentation frame (FNV-1a) each considered frame and exports a PNG via raylib only when the hash changes.

All environment variables use the PS2X_ prefix (PS2X_DIAG, PS2X_WATCH, PS2X_REC, PS2X_REC_INTERVAL).

Design decisions

  • Draw stats behind the gate, not unconditional. The [gs-activity] counters could have been plain atomics bumped on every primitive/transfer, but a serializing lock-prefixed RMW on the draw-dispatch hot path is too much to pay when diagnostics are off. They live inside the ps2_diag::enabled() gate; the [gs-activity] reader still gets them under PS2X_DIAG=1.
  • Runtime watch hook rather than a compile-time #ifdef. Writer-PC capture is wired through a runtime-armed atomic bool so it can be toggled per run without rebuilding the recompiled corpus. A build-time #ifdef was rejected: it would leave the feature dormant by default, and it is ODR-fragile for an inline hook in a header that the recompiled units include.
  • CLUT dump keyed on the full addressing tuple. The dedup key is (cbp, cpsm, csa, csm, sourcePsm) rather than just (cbp, cpsm, csa), so a different addressing mode (csm) or index width (sourcePsm) under the same base is not silently dropped.
  • [gs-activity] triple is read, not snapshotted. prims/imgbytes/lastfbp are three independent relaxed loads; the printed triple may be torn. It is a human-read headline, never a control-flow input.

Zero-cost-when-off verification

objdump of GS::vertexKick confirms the only lock xadd in the function sits after the ps2_diag::enabled() gate branch, so the diagnostics-off fall-through never reaches it — the claim is verified in the emitted code, not merely asserted.

The one place the layer is not literally zero-cost-when-off is the per-store writer-watch check: with no watch armed, every recompiled store pays one relaxed load of a cache-resident global bool plus a predicted-not-taken branch, inside the store's pre-existing fast path for ordinary guest addresses — no locked RMW, no I/O, no allocation. This is the minimum needed to offer runtime-toggleable writer-PC capture without a full corpus rebuild. When a watch is armed, onGuestWrite takes registryMutex per matching store.

Tests

New "PS2 Runtime Observability" suite (11 tests): should_log bound math (2000 counts → exactly 19 lines); watch seed / 2-change / 2000-change (→ exactly 19 lines) / disabled-gate / unregistered cases; writer-PC attribution through the real ps2TraceGuestWrite hook; PS2X_WATCH string parsing that arms a watch and fires it through the store hook; CSM1 dump swizzle (logical 8–15 → physical 16–23); CSM2 linear dump; dump-once-per-(cbp, cpsm, csa, csm, sourcePsm)-key; and [gs:image] field correctness driven through a real IMAGE-mode GIF packet.

Full suite: 307/307 passing (Studio-OFF build). The Debug build of ps2_runtime + tests is clean with no new warnings.

Limitations

  • Writer-PC capture adds a small always-present per-store cost (one relaxed load + a predicted-not-taken branch); see the verification section above.
  • Fiber/scheduler internals are not instrumented; this layer covers the GS/DMA pipeline, guest memory, lifecycle/IO, and presentation.

Add an observability layer to the PS2 runtime that is entirely opt-in and
does nothing unless explicitly enabled, so a normal build pays no runtime
cost for it.

- PS2X_DIAG gates a set of diagnostic probes ([gs-activity], [gs:image],
  [gs:clut-dump], ...). When the gate is off the probes compile to a single
  relaxed atomic load and an untaken branch; the honest residual is one such
  check per guarded site (notably per guest store), never the work behind it.

- PS2X_WATCH parses a list of guest-address watches and reports every change
  to a watched word together with the guest PC of the writing store, captured
  through the existing guest-write hook. Arming any watch turns on the full
  diagnostic stream (PS2X_DIAG behaviour), since the watch reporting rides the
  same log path.

- PS2X_REC / PS2X_REC_INTERVAL drive a frame recorder that periodically
  snapshots frame state for offline inspection.

- Fix the CSM1 CLUT dump: logical palette indices are resolved through the
  same resolveClutIndex path used by live texture sampling, so the CSM1
  swizzle (logical 8-15 -> physical 16-23) is applied by construction while
  CSM2 stays linear. Factor the palette texel fetch into readClutRgba, shared
  by the dump and the sampler so they cannot drift.

- The [gs:clut-dump] dedup key is the full addressing tuple
  (cbp, cpsm, csa, csm, sourcePsm), not just (cbp, cpsm, csa): a distinct
  addressing mode or index width under the same base is a genuinely different
  palette view and must not be dropped.

- Add a "PS2 Runtime Observability" test suite (11 tests): should_log bound
  math, watch seed/change/disabled/unregistered cases, writer-PC attribution
  through the real guest-write hook, PS2X_WATCH string parsing, CSM1 and CSM2
  dump behaviour, [gs:image] field correctness through a real IMAGE-mode GIF
  packet, and a discriminating dump-dedup test that holds (cbp, cpsm, csa)
  fixed and varies csm and sourcePsm each alone to prove the 5-tuple key.
@smmathews
smmathews force-pushed the feature/10-runtime-observability branch from 847de7c to 198a0c8 Compare July 7, 2026 19:35
@smmathews
smmathews marked this pull request as ready for review July 7, 2026 19:37
# Conflicts:
#	ps2xRuntime/src/lib/ps2_runtime.cpp
- elf_parser.h: include <cstdint> before <elfio/elfio.hpp>. ELFIO's
  elf_types.hpp uses uint16_t/uint32_t/uint64_t without including
  <cstdint> itself; newer libstdc++ no longer pulls those in
  transitively, so this failed to compile with the toolchain here.

- ps2_log.h / observability probes: upstream ran-j#167 flipped the default
  of PS2_RUNTIME_LOGS from 1 to 0, so RUNTIME_LOG now compiles to a
  no-op in a default (non -DPS2X_ENABLE_RUNTIME_LOGS) build -- which
  is exactly how CI builds and runs the test binary. That silently
  broke every PS2X_DIAG-gated observability probe added in this
  branch ([gs:*], [watch], [dma:chain], [fioOpen], [fioRead], [exit],
  clut-dump), since they all logged through RUNTIME_LOG and are
  supposed to work whenever PS2X_DIAG=1 is set at runtime, independent
  of any build-time logging flag.

  Added PS2X_DIAG_LOG, a sibling macro with the same body as
  RUNTIME_LOG but without the PS2_RUNTIME_LOGS/AGRESSIVE_LOGS compile
  gate, and switched every probe introduced by the observability
  feature to use it. Pre-existing RUNTIME_LOG call sites are left
  alone, so upstream's quieter default build behavior is preserved.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant