diff --git a/docs/HOST_WALL_TIME_RINGS.md b/docs/HOST_WALL_TIME_RINGS.md new file mode 100644 index 00000000..f1be8b8b --- /dev/null +++ b/docs/HOST_WALL_TIME_RINGS.md @@ -0,0 +1,37 @@ +# Always-on host wall-time rings (hitch attribution) + +A gameplay hitch is an unusually long frame, whether from guest execution, host work, or waiting. +These rings record where the time went, continuously from process start in every build, so a probe never arms +anything: it queries a window that already happened. + +| Ring | TCP command | Holds | +|------|-------------|-------| +| frame stamps | `frame_wall_ring {"from":SEQ,"n":N}` | flat `f` array with `stride: 6`: `[guest frame, wall us, interpreter insns, static checks, process page faults, process read KiB]`; counters use their low 32 bits; 131072 frames (~36 min at 60 Hz) | +| spans | `host_span_ring {"from":SEQ,"n":N}` | `[seq, kind, t0_us, dur_us, frame, emu, arg]` for every named blocking-capable operation of 50 us or more, 65536 spans | +| host CPU sampler (debug-tools builds) | `host_profile {"frame_lo":A,"frame_hi":B}` | 1 kHz instruction-pointer samples of the emulation thread, 1 Mi samples (~17 min), with per-module totals for samples outside the exe | + +Wall time is microseconds since the first ring call. `emu` is 1 for the emulation thread, 0 for a +worker (compiler child, publication preparer). + +Readers and writers use nonblocking slot ownership. A contended sample may be dropped or skipped; +readers only return fully published records from the requested ring generation. A missing frame +stamp leaves an interval spanning multiple frames: do not report that interval as one long frame. +Legacy frame captures had three or four columns and no `stride`; consumers must identify their +layout before interpreting them. Process counters include worker threads, and page faults include +soft faults, so neither counter alone proves a blocking disk read. + +Span kinds (`runtime/include/host_span_ring.h`): `autocapture_tick`, `provider_poll`, +`publish_commit`, `loader_rescan`, `dll_register`, `lazy_load` (a synchronous first map of a shard +at a dispatch miss), `capture_on_dma`, `capture_before_dma`, `ac_request` (spawning the compiler), +`ac_done_join`, `ac_prepare_image` (worker), `ac_child` (compiler lifetime, worker), +`overlay_dispatch`, `mod_work`, `frame_present`, and `disc_read` (cooked or raw sector read). + +Reading a hitch: per frame, subtract the union of overlapping emulation-thread spans from the wall +delta to find the time no span explains; nested spans must not be counted twice. Then ask the host sampler for that frame window. A title's report tool +joins them (`LegendOfDragoonRecomp/tools/lod_hitch_report.py`). + +Findings the rings produced (LoD, 2026-10-12): a toolchain staged from another emitter than the +runtime wrote every shard where the loader never looks (now refused loudly, see +`autocompile_check_toolchain_hash`), and shards compiled during play were mapped by the emulation +thread because `compile_overlays.py` never announced them (now `PSX_SHARD_PUBLISHED`, see +`announce_published_shard`). diff --git a/runtime/CMakeLists.txt b/runtime/CMakeLists.txt index c4d96b5d..9ca3189e 100644 --- a/runtime/CMakeLists.txt +++ b/runtime/CMakeLists.txt @@ -206,7 +206,7 @@ if(BUILD_TESTING) add_test(NAME boot_state_execution_test COMMAND boot_state_execution_test) add_executable(static_match_cache_test tests/test_static_match_cache.c - src/overlay_loader.c src/crc32.c) + src/overlay_loader.c src/host_span_ring.c src/crc32.c) target_include_directories(static_match_cache_test PRIVATE include) target_compile_definitions(static_match_cache_test PRIVATE PSX_HAS_OVERLAY_DISPATCH PSX_NO_DEBUG_TOOLS) @@ -1198,6 +1198,7 @@ if(BUILD_TESTING) add_executable(overlay_capture_retry_test tests/test_overlay_capture_retry.cpp src/overlay_capture.c + src/host_span_ring.c src/psx_ram_geometry.c) target_include_directories(overlay_capture_retry_test PRIVATE include ${PSX_SDL_INCLUDE_DIRS}) @@ -1375,6 +1376,7 @@ if(BUILD_TESTING) add_executable(mod_runtime_test tests/test_mod_runtime.cpp src/iso_reader_c.cpp + src/host_span_ring.c src/mod_runtime.cpp src/mod_netplay.c src/mod_packages.cpp @@ -1421,6 +1423,7 @@ if(BUILD_TESTING) add_executable(netplay_view_mods_test tests/test_netplay_view_mods.cpp src/iso_reader_c.cpp + src/host_span_ring.c src/mod_runtime.cpp src/mod_netplay.c src/mod_packages.cpp @@ -1492,7 +1495,8 @@ if(BUILD_TESTING) if(WIN32) add_executable(autocompile_publication_test tests/test_autocompile_publication.c - src/autocompile.c) + src/autocompile.c + src/host_span_ring.c) target_include_directories(autocompile_publication_test PRIVATE include) target_compile_definitions(autocompile_publication_test PRIVATE PSX_AUTOCOMPILE_TEST=1) @@ -1504,12 +1508,35 @@ if(BUILD_TESTING) # broken autocompile silently degrades the whole run to the interpreter. add_executable(autocompile_degraded_test tests/test_autocompile_degraded.c - src/autocompile.c) + src/autocompile.c + src/host_span_ring.c) target_include_directories(autocompile_degraded_test PRIVATE include) add_test(NAME autocompile_degraded_test COMMAND autocompile_degraded_test) + + # A toolchain staged from a different emitter writes shards into a cache directory the + # runtime never reads (LoD playtest 2026-10-12); the runtime must refuse it loudly. + add_executable(autocompile_toolchain_hash_test + tests/test_autocompile_toolchain_hash.c + src/autocompile.c + src/host_span_ring.c) + target_include_directories(autocompile_toolchain_hash_test PRIVATE include) + add_test(NAME autocompile_toolchain_hash_test + COMMAND autocompile_toolchain_hash_test) endif() + # Always-on wall-time frame/span rings (host_span_ring.h): the hitch-attribution + # rings every runtime stall probe reads. + add_executable(host_span_ring_test + tests/test_host_span_ring.c + src/host_span_ring.c) + target_include_directories(host_span_ring_test PRIVATE include) + if(UNIX) + find_package(Threads REQUIRED) + target_link_libraries(host_span_ring_test PRIVATE Threads::Threads) + endif() + add_test(NAME host_span_ring_test COMMAND host_span_ring_test) + # ---- previously-unregistered standalone tests ------------------------- # These 16 existed in runtime/tests/ with no add_test() entry. Their only # build instructions were a gcc command line in each file's header comment, @@ -2006,6 +2033,7 @@ if(BUILD_TESTING) add_test(NAME overlay_retry_c11_test COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_SOURCE_DIR}/tests/test_overlay_retry_c11.py --compiler ${CMAKE_C_COMPILER}) endif() add_test(NAME setup_bios_assets_test COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_SOURCE_DIR}/tests/test_setup_bios_assets.py) + add_test(NAME compile_overlays_publish_marker_test COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_SOURCE_DIR}/tests/test_compile_overlays_publish_marker.py) if(CMAKE_CXX_COMPILER_ID MATCHES "GNU|Clang") add_test(NAME launch_disc_path_test COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_SOURCE_DIR}/tests/test_launch_disc_path.py --compiler ${CMAKE_CXX_COMPILER}) add_test(NAME persisted_settings_paths_test COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_SOURCE_DIR}/tests/test_persisted_settings_paths.py --compiler ${CMAKE_CXX_COMPILER}) diff --git a/runtime/include/autocompile.h b/runtime/include/autocompile.h index 0db386ec..bd4f88f5 100644 --- a/runtime/include/autocompile.h +++ b/runtime/include/autocompile.h @@ -8,6 +8,8 @@ #ifndef PSXRECOMP_AUTOCOMPILE_H #define PSXRECOMP_AUTOCOMPILE_H +#include + #ifdef __cplusplus extern "C" { #endif @@ -26,6 +28,19 @@ int autocompile_configured(void); * cache location: no per-game config, no drift. */ void autocompile_set_cache_paths(const char *cache_dir, const char *captures); +/* Is the staged overlay toolchain the one THIS runtime was built with? + * + * The shard cache directory carries the codegen hash (gcc//cg__...). A toolchain + * staged from an older emitter writes its shards under its own hash, a directory this runtime + * never reads: every compile succeeds, nothing is ever loaded, every overlay stays interpreted + * and the same regions are recompiled for the whole session (LoD playtest 2026-10-12: 27 + * compile runs, 0 shards loaded). Reads /overlay_codegen_hash.h and + * compares its PSX_OVERLAY_CODEGEN_HASH with `runtime_hash`. + * Returns 1 when usable or unknown (no/unparseable header, or runtime_hash == 0); returns 0 and + * records a degraded reason (autocompile_status "degraded_reason") on a mismatch. The caller + * must then NOT configure the bundled toolchain command. */ +int autocompile_check_toolchain_hash(const char *toolchain_include_dir, uint32_t runtime_hash); + /* Probe whether a C compiler is actually reachable on PATH (gcc/cc/clang) — the * REAL "developer machine" signal, distinct from autocompile_configured() which * only reports that a command STRING is set (the shipped game.toml always sets diff --git a/runtime/include/host_sampler.h b/runtime/include/host_sampler.h index 069ff1b5..2fd3ddf2 100644 --- a/runtime/include/host_sampler.h +++ b/runtime/include/host_sampler.h @@ -8,7 +8,9 @@ extern "C" { #endif -#define HOST_SAMPLER_CAP 65536u /* ~65 s at 1 kHz */ +/* 1 Mi samples: ~17 minutes at 1 kHz, enough to keep a whole load-transition route (16 MB, + * debug-tools builds only) so a hitch found afterwards still has its host call sites. */ +#define HOST_SAMPLER_CAP 1048576u typedef struct HostSample { uint64_t rva; /* instruction pointer minus the executable's base */ diff --git a/runtime/include/host_span_ring.h b/runtime/include/host_span_ring.h new file mode 100644 index 00000000..4026a07b --- /dev/null +++ b/runtime/include/host_span_ring.h @@ -0,0 +1,94 @@ +#ifndef PSX_HOST_SPAN_RING_H +#define PSX_HOST_SPAN_RING_H +/* Always-on host wall-time rings: where an emulation-thread stall comes from. + * + * Two rings, both written continuously from process start in EVERY build + * (Release too); probes only ever QUERY a window that already happened: + * + * - frame stamps: one {guest frame, wall us} per guest frame (131072 frames, + * ~36 min at 60 Hz). Successive deltas are the per-frame wall time, so a + * hitch is visible headless as well as windowed (no GL present ring needed). + * - spans: every named blocking-capable runtime operation (loader, capture, + * publication commit, cache rescan, autocompile spawn/prepare/compile child) + * as {kind, start wall us, duration us, guest frame, thread class, arg}. + * The emulation thread's spans are the candidates for a hitch; background + * spans show the work that fed them. + * + * Wall time is microseconds since the first call in the process (monotonic). + * Writers may be different threads. Per-slot ownership and publication sequence + * validation prevent torn or overwritten rows. Contended samples are dropped; + * diagnostics never wait for a reader to release a slot. + * + * Reading: TCP "host_span_ring" / "frame_wall_ring"; a title's hitch report + * tool joins them (LegendOfDragoonRecomp tools/lod_hitch_report.py). */ +#include + +#ifdef __cplusplus +extern "C" { +#endif + +typedef enum HostSpanKind { + HSPAN_NONE = 0, + HSPAN_AUTOCAPTURE_TICK, /* emu: overlay_autocapture_tick (whole) */ + HSPAN_PROVIDER_POLL, /* emu: code provider poll_main (whole) */ + HSPAN_PUBLISH_COMMIT, /* emu: overlay_loader_commit_published */ + HSPAN_LOADER_RESCAN, /* emu: overlay_loader_rescan */ + HSPAN_DLL_REGISTER, /* emu: parse manifest + load_overlay_dll */ + HSPAN_LAZY_LOAD, /* emu: try_load_region (miss -> cache load) */ + HSPAN_CAPTURE_ON_DMA, /* emu: overlay_capture_on_dma (CD/DMA arrival) */ + HSPAN_CAPTURE_BEFORE_DMA, /* emu: overlay_capture_before_dma (evidence save) */ + HSPAN_AC_REQUEST, /* emu: autocompile_request (spawn compiler) */ + HSPAN_AC_DONE_JOIN, /* emu: poll_main joining finished workers */ + HSPAN_AC_PREPARE_IMAGE, /* bg : publication preparer LoadLibrary */ + HSPAN_AC_CHILD, /* bg : compiler child process lifetime */ + HSPAN_OVERLAY_DISPATCH, /* emu: overlay_loader_dispatch slow path */ + HSPAN_MOD_WORK, /* emu: resident pack / mod host work */ + HSPAN_FRAME_PRESENT, /* emu: frontend present for the frame */ + HSPAN_DISC_READ, /* emu: one sector read from the disc image (arg lba) */ + HSPAN_KIND_COUNT +} HostSpanKind; + +typedef struct HostSpan { + uint64_t t0_us; /* start, wall us since process clock origin */ + uint32_t dur_us; /* duration (saturates at ~71 min) */ + uint32_t frame; /* guest frame when the span ended */ + uint32_t arg; /* kind-specific (address, ok flag, count) */ + uint16_t kind; /* HostSpanKind */ + uint16_t emu; /* 1 = emulation thread, 0 = background */ +} HostSpan; + +/* Wall microseconds since the process clock origin. */ +uint64_t host_clock_us(void); + +/* Open / close a span. begin returns the start stamp; end records it. */ +uint64_t host_span_begin(void); +void host_span_end(HostSpanKind kind, uint64_t t0_us, uint32_t arg); +/* Record a span whose duration the caller already measured. */ +void host_span_record(HostSpanKind kind, uint64_t t0_us, uint64_t dur_us, uint32_t arg); + +uint64_t host_span_total(void); +int host_span_get(uint64_t seq, HostSpan *out); +const char *host_span_kind_name(unsigned kind); +/* 65536 spans; spans shorter than HOST_SPAN_MIN_US are not recorded (the per-frame + * tick wrappers would otherwise flood the ring; a hitch is milliseconds). */ +#define HOST_SPAN_RING_CAP 65536u +#define HOST_SPAN_MIN_US 50u + +/* Stamp guest frame `frame` at the current wall time. Also marks the calling + * thread as the emulation thread for span attribution. Call once per frame. + * interp_insns is the low 32 bits of the cumulative count of guest instructions run by the + * interpreter (successive differences = interpreter work in that frame); static_checks likewise + * counts static-AOT dispatch checks (guest calls into statically compiled code), the work a native + * stretch of guest code between two vblanks does. Each stamp also records the process's cumulative + * page-fault count and disk-read volume (KiB), so a frame that waited on the OS (code or data pages + * paged in from disk) is told apart from one that computed. */ +void host_frame_stamp(uint32_t frame, uint32_t interp_insns, uint32_t static_checks); +uint64_t host_frame_stamp_total(void); +int host_frame_stamp_get(uint64_t seq, uint32_t *frame, uint64_t *t_us, uint32_t *interp_insns, + uint32_t *static_checks, uint32_t *page_faults, uint32_t *io_read_kb); +#define HOST_FRAME_STAMP_CAP 131072u + +#ifdef __cplusplus +} +#endif +#endif diff --git a/runtime/include/overlay_loader.h b/runtime/include/overlay_loader.h index ac985513..8203211f 100644 --- a/runtime/include/overlay_loader.h +++ b/runtime/include/overlay_loader.h @@ -119,6 +119,10 @@ void overlay_loader_resync_validation_after_restore(void); * (loaded DLLs stay loaded); emu thread only. */ void overlay_loader_rescan(void); +/* The codegen hash this runtime was built with (PSX_OVERLAY_CODEGEN_HASH, 0 if unknown). It names the + * shard cache directory, so a toolchain staged from a different emitter writes where nobody reads. */ +unsigned overlay_loader_codegen_hash(void); + /* Two-phase live publication: the compile-output watcher maps a freshly * published image off the emulation thread, then the emulation thread performs * callback wiring, manifest validation, and candidate registration. The opaque diff --git a/runtime/runtime.cmake b/runtime/runtime.cmake index b248d6a6..58be92e4 100644 --- a/runtime/runtime.cmake +++ b/runtime/runtime.cmake @@ -421,6 +421,7 @@ set(PSXRECOMP_RUNTIME_SOURCES ${PSXRECOMP_ROOT}/runtime/src/memcard.c ${PSXRECOMP_ROOT}/runtime/src/debug_server.c ${PSXRECOMP_ROOT}/runtime/src/host_sampler.c + ${PSXRECOMP_ROOT}/runtime/src/host_span_ring.c ${PSXRECOMP_ROOT}/runtime/src/debug_trace_ranges.c ${PSXRECOMP_ROOT}/runtime/src/dirty_ram_interp.c ${PSXRECOMP_ROOT}/runtime/src/draw_distance.c diff --git a/runtime/src/autocompile.c b/runtime/src/autocompile.c index 2dad0311..22842246 100644 --- a/runtime/src/autocompile.c +++ b/runtime/src/autocompile.c @@ -4,6 +4,7 @@ * and pick every shard up with the batch-end cache rescan. The manual * compile_overlays.py flow still works everywhere. */ #include "autocompile.h" +#include "host_span_ring.h" #include "overlay_loader.h" #include /* autocompile_set_degraded takes a format + varargs */ @@ -160,6 +161,32 @@ static void autocompile_set_degraded(const char *fmt, ...) { va_end(ap); } +int autocompile_check_toolchain_hash(const char *toolchain_include_dir, uint32_t runtime_hash) { + if (!toolchain_include_dir || !toolchain_include_dir[0] || runtime_hash == 0) return 1; + char path[1024]; + snprintf(path, sizeof(path), "%s/overlay_codegen_hash.h", toolchain_include_dir); + FILE *f = fopen(path, "rb"); + if (!f) return 1; + char text[1024]; + size_t n = fread(text, 1, sizeof(text) - 1, f); + fclose(f); + text[n] = '\0'; + const char *key = strstr(text, "PSX_OVERLAY_CODEGEN_HASH"); + if (!key) return 1; + key += strlen("PSX_OVERLAY_CODEGEN_HASH"); + char *end = NULL; + unsigned long tk = strtoul(key, &end, 0); + if (end == key) return 1; + if ((uint32_t)tk == runtime_hash) return 1; + autocompile_set_degraded( + "stale overlay toolchain: %s names codegen hash 0x%08lx but this runtime was built with " + "0x%08x, so compiled shards would land in a cache directory the runtime never reads and " + "every overlay would stay interpreted. Restage overlay_toolchain/ from the framework this " + "runtime was built against (psxrecomp_cli.py rebuild, or tools/release_stage.py).", + path, tk, (unsigned)runtime_hash); + return 0; +} + const char *autocompile_degraded_reason(void) { return s_degraded[0] ? s_degraded : NULL; } @@ -389,7 +416,9 @@ static DWORD WINAPI publish_prepare_thread_main(LPVOID unused) { int attempts = 0; for (;;) { QueryPerformanceCounter(&q0); + const uint64_t span_t0 = host_span_begin(); item->image = overlay_loader_prepare_published(item->path); + host_span_end(HSPAN_AC_PREPARE_IMAGE, span_t0, item->image ? 1u : 0u); QueryPerformanceCounter(&q1); attempts++; if (item->image || attempts >= AC_PREPARE_ATTEMPTS) break; @@ -608,6 +637,7 @@ typedef struct { HANDLE read_pipe; HANDLE proc; } WatchCtx; static DWORD WINAPI watch_thread(LPVOID arg) { WatchCtx *ctx = (WatchCtx *)arg; + const uint64_t watch_t0 = host_span_begin(); char buf[1024]; DWORD got; while (ReadFile(ctx->read_pipe, buf, sizeof(buf), &got, NULL) && got > 0) @@ -616,6 +646,7 @@ static DWORD WINAPI watch_thread(LPVOID arg) { WaitForSingleObject(ctx->proc, INFINITE); DWORD code = (DWORD)-1; GetExitCodeProcess(ctx->proc, &code); + host_span_end(HSPAN_AC_CHILD, watch_t0, (uint32_t)code); EnterCriticalSection(&s_out_lock); /* A marker/result line cut off by child termination is not trustworthy. * Completion will force the idempotent directory rescan instead. */ @@ -1050,7 +1081,15 @@ int autocompile_toolchain_available(void) { return found; } +static int autocompile_request_impl(void); int autocompile_request(void) { + const uint64_t span_t0 = host_span_begin(); + int started = autocompile_request_impl(); + if (started) host_span_end(HSPAN_AC_REQUEST, span_t0, 0); + return started; +} + +static int autocompile_request_impl(void) { /* DONE owns an unconsumed cache rescan/result. Only the emulation-thread * poll may return it to IDLE; never overwrite it with another child. */ if (!autocompile_configured() || ac_state_load() != AC_IDLE) return 0; @@ -1396,6 +1435,7 @@ void autocompile_poll_main(void) { } #else if (publish_pending()) return; + const uint64_t join_t0 = host_span_begin(); /* DONE is published immediately before the preparer returns. Join both * per-run workers before exposing IDLE, so a new run cannot inherit a live * consumer of the shared FIFO. Neither worker needs the emulation thread. */ @@ -1415,6 +1455,7 @@ void autocompile_poll_main(void) { CloseHandle(s_job); s_job = NULL; } + host_span_end(HSPAN_AC_DONE_JOIN, join_t0, 0); #endif /* Streaming parsing survives arbitrarily large chained post-processing * output. Retain the tail scan as a compatibility fallback for output diff --git a/runtime/src/debug_server.c b/runtime/src/debug_server.c index a50ea680..0f278728 100644 --- a/runtime/src/debug_server.c +++ b/runtime/src/debug_server.c @@ -20,6 +20,7 @@ #include "host_launch_timing.h" #include "host_sampler.h" #include "savestate.h" +#include "host_span_ring.h" #include "guest_cycle_profile.h" #include "host_osd.h" #include "psx_video_timing.h" @@ -5443,7 +5444,7 @@ static void handle_geom_correction(int id, const char *json) /* host_profile — histogram of the always-on host CPU sampler (host_sampler.c) * over a window of the ring: {"cmd":"host_profile","since":SEQ} or * {"cmd":"host_profile","frames":N} (the last N guest frames), optional - * "pass":1 (only samples inside render passes) / "pass":0 (outside), "top":K. + * "frame_lo"/"frame_hi" (an absolute guest-frame window), "pass":1 (only samples inside render passes) / "pass":0 (outside), "top":K. * Addresses are executable-relative; tools/host_profile.py names them. Take * "seq" from one reply as "since" of the next to profile what ran between. */ static void handle_host_profile(int id, const char *json) @@ -5455,6 +5456,9 @@ static void handle_host_profile(int id, const char *json) const uint64_t oldest = seq > HOST_SAMPLER_CAP ? seq - HOST_SAMPLER_CAP : 0; int since = json_get_int(json, "since", -1); const int frames = json_get_int(json, "frames", -1); + /* Optional absolute guest-frame window (inclusive): profile exactly one hitch. */ + const int frame_lo_abs = json_get_int(json, "frame_lo", -1); + const int frame_hi_abs = json_get_int(json, "frame_hi", -1); const int pass = json_get_int(json, "pass", -1); int top = json_get_int(json, "top", 60); if (top < 1) top = 1; @@ -5469,6 +5473,8 @@ static void handle_host_profile(int id, const char *json) HostSample smp; if (!host_sampler_get(i, &smp)) continue; if (frames > 0 && (int32_t)(smp.frame - frame_lo) < 0) continue; + if (frame_lo_abs >= 0 && smp.frame < (uint32_t)frame_lo_abs) continue; + if (frame_hi_abs >= 0 && smp.frame > (uint32_t)frame_hi_abs) continue; if (pass >= 0 && (int)smp.in_pass != pass) continue; total++; int b = 0; @@ -5479,7 +5485,41 @@ static void handle_host_profile(int id, const char *json) } counts[b]++; } - size_t cap = 256 + (size_t)top * 48; + /* Where did the samples that are NOT in this executable land? A hitch spent inside the + * GL driver, the OS loader or the audio stack shows up here by module name ("modules": + * [[name, samples], ...], the exe itself as "(exe)"), where the bare addresses above + * cannot be mapped to anything without that module's symbols. */ + char modnames[24][96]; uint64_t modcount[24]; int nmod = 0; +#ifdef _WIN32 + { + const HMODULE exe_mod = GetModuleHandleA(NULL); + const uint64_t base = host_sampler_image_base(); + for (int b = 0; b < nb; b++) { + HMODULE h = NULL; + const char *name = "(unknown)"; + char path[260]; + if (rvas[b] == 0) { + name = "(non-image pc)"; + } else if (GetModuleHandleExA(GET_MODULE_HANDLE_EX_FLAG_FROM_ADDRESS | + GET_MODULE_HANDLE_EX_FLAG_UNCHANGED_REFCOUNT, + (LPCSTR)(uintptr_t)(base + rvas[b]), &h) && h) { + if (h == exe_mod) name = "(exe)"; + else if (GetModuleFileNameA(h, path, sizeof path)) { + name = strrchr(path, '\\'); + name = name ? name + 1 : path; + } + } + int m = 0; + while (m < nmod && strcmp(modnames[m], name) != 0) m++; + if (m == nmod) { + if (nmod == 24) { m = 23; } + else { nmod++; snprintf(modnames[m], sizeof modnames[m], "%s", name); modcount[m] = 0; } + } + modcount[m] += counts[b]; + } + } +#endif + size_t cap = 256 + (size_t)top * 48 + 24u * 128u; char *buf = (char *)malloc(cap); if (!buf) { send_err(id, "oom"); return; } size_t n = (size_t)snprintf(buf, cap, @@ -5497,11 +5537,82 @@ static void handle_host_profile(int id, const char *json) (unsigned long long)rvas[best], counts[best]); counts[best] = 0; } + n += (size_t)snprintf(buf + n, cap - n, "],\"modules\":["); + for (int m = 0; m < nmod; m++) + n += (size_t)snprintf(buf + n, cap - n, "%s[\"%s\",%llu]", m ? "," : "", modnames[m], + (unsigned long long)modcount[m]); snprintf(buf + n, cap - n, "]}"); send_fmt("%s", buf); free(buf); } +/* host_span_ring / frame_wall_ring - always-on wall-time rings (host_span_ring.h). + * {"cmd":"host_span_ring","from":SEQ,"n":N} spans with seq >= from (default: oldest) + * -> {total, oldest, events:[[seq, kind, t0_us, dur_us, frame, emu, arg], ...]} + * {"cmd":"frame_wall_ring","from":SEQ,"n":N} per-guest-frame wall stamps + * -> {total, oldest, now_us, f:[frame, t_us, interp_insns_lo32, static_checks_lo32, page_faults, io_read_kb, ...]} + * Both read a window that already happened; nothing is armed. */ +static void handle_host_span_ring(int id, const char *json) +{ + const uint64_t total = host_span_total(); + const uint64_t oldest = total > HOST_SPAN_RING_CAP ? total - HOST_SPAN_RING_CAP : 0; + int from_i = json_get_int(json, "from", -1); + int n = json_get_int(json, "n", 4096); + if (n < 1) n = 1; + if (n > (int)HOST_SPAN_RING_CAP) n = (int)HOST_SPAN_RING_CAP; + uint64_t from = from_i >= 0 ? (uint64_t)from_i : oldest; + if (from < oldest) from = oldest; + size_t cap = 160 + (size_t)n * 96; + char *buf = (char *)malloc(cap); + if (!buf) { send_err(id, "oom"); return; } + size_t pos = (size_t)snprintf(buf, cap, + "{\"id\":%d,\"ok\":true,\"total\":%llu,\"oldest\":%llu,\"now_us\":%llu,\"events\":[", + id, (unsigned long long)total, (unsigned long long)oldest, + (unsigned long long)host_clock_us()); + int first = 1, emitted = 0; + for (uint64_t q = from; q < total && emitted < n && pos + 128 < cap; q++) { + HostSpan sp; + if (!host_span_get(q, &sp)) continue; + pos += (size_t)snprintf(buf + pos, cap - pos, "%s[%llu,\"%s\",%llu,%u,%u,%u,%u]", + first ? "" : ",", (unsigned long long)q, host_span_kind_name(sp.kind), + (unsigned long long)sp.t0_us, sp.dur_us, sp.frame, sp.emu, sp.arg); + first = 0; emitted++; + } + snprintf(buf + pos, cap - pos, "]}"); + send_fmt("%s", buf); + free(buf); +} + +static void handle_frame_wall_ring(int id, const char *json) +{ + const uint64_t total = host_frame_stamp_total(); + const uint64_t oldest = total > HOST_FRAME_STAMP_CAP ? total - HOST_FRAME_STAMP_CAP : 0; + int from_i = json_get_int(json, "from", -1); + int n = json_get_int(json, "n", 20000); + if (n < 1) n = 1; + if (n > (int)HOST_FRAME_STAMP_CAP) n = (int)HOST_FRAME_STAMP_CAP; + uint64_t from = from_i >= 0 ? (uint64_t)from_i : oldest; + if (from < oldest) from = oldest; + size_t cap = 192 + (size_t)n * 64; + char *buf = (char *)malloc(cap); + if (!buf) { send_err(id, "oom"); return; } + size_t pos = (size_t)snprintf(buf, cap, + "{\"id\":%d,\"ok\":true,\"total\":%llu,\"oldest\":%llu,\"from\":%llu,\"now_us\":%llu,\"stride\":6,\"f\":[", + id, (unsigned long long)total, (unsigned long long)oldest, + (unsigned long long)from, (unsigned long long)host_clock_us()); + int first = 1, emitted = 0; + for (uint64_t q = from; q < total && emitted < n && pos + 96 < cap; q++) { + uint32_t fr, ii, ck, pf, io; uint64_t t; + if (!host_frame_stamp_get(q, &fr, &t, &ii, &ck, &pf, &io)) continue; + pos += (size_t)snprintf(buf + pos, cap - pos, "%s%u,%llu,%u,%u,%u,%u", first ? "" : ",", fr, + (unsigned long long)t, ii, ck, pf, io); + first = 0; emitted++; + } + snprintf(buf + pos, cap - pos, "]}"); + send_fmt("%s", buf); + free(buf); +} + /* pgxp_shadow — read PGXP shadow slots: {"cmd":"pgxp_shadow","addr":A, * "count":N} walks N guest words from A (RAM / scratchpad); "space":"gpr" or * "gte" with "index"/"count" reads register shadows instead. Each slot: the @@ -15978,6 +16089,8 @@ static const CmdEntry s_commands[] = { { "pgxp_store_ring", handle_pgxp_store_ring }, { "pgxp_shadow", handle_pgxp_shadow }, { "host_profile", handle_host_profile }, + { "host_span_ring", handle_host_span_ring }, + { "frame_wall_ring", handle_frame_wall_ring }, { "pgxp_miss_ring", handle_pgxp_miss_ring }, { "ws_aspect_cone_site", handle_ws_aspect_cone_site }, { "ws_margin", handle_ws_margin }, diff --git a/runtime/src/host_span_ring.c b/runtime/src/host_span_ring.c new file mode 100644 index 00000000..c1c8fd79 --- /dev/null +++ b/runtime/src/host_span_ring.c @@ -0,0 +1,184 @@ +/* host_span_ring.c - always-on wall-time frame + span rings. See host_span_ring.h. */ +#include "host_span_ring.h" + +#include +#include + +#ifdef _WIN32 +#include +#include +static uint64_t qpc_now_us(void) { + static _Atomic uint64_t frequency; + uint64_t freq = atomic_load_explicit(&frequency, memory_order_relaxed); + LARGE_INTEGER c; + if (!freq) { + LARGE_INTEGER value; + QueryPerformanceFrequency(&value); + freq = (uint64_t)value.QuadPart; + atomic_store_explicit(&frequency, freq, memory_order_relaxed); + } + QueryPerformanceCounter(&c); + return ((uint64_t)c.QuadPart / freq) * 1000000ull + + ((uint64_t)c.QuadPart % freq) * 1000000ull / freq; +} +static uint64_t this_thread_id(void) { return (uint64_t)GetCurrentThreadId(); } +/* Cumulative page faults and disk bytes read by this process. */ +static void proc_counters(uint32_t *faults, uint32_t *io_kb) { + PROCESS_MEMORY_COUNTERS pmc; + IO_COUNTERS io; + *faults = 0; *io_kb = 0; + if (K32GetProcessMemoryInfo(GetCurrentProcess(), &pmc, sizeof pmc)) *faults = (uint32_t)pmc.PageFaultCount; + if (GetProcessIoCounters(GetCurrentProcess(), &io)) *io_kb = (uint32_t)(io.ReadTransferCount >> 10); +} +#else +#include +#include +#include +static uint64_t qpc_now_us(void) { + struct timespec ts; + clock_gettime(CLOCK_MONOTONIC, &ts); + return (uint64_t)ts.tv_sec * 1000000ull + (uint64_t)ts.tv_nsec / 1000ull; +} +static uint64_t this_thread_id(void) { return (uint64_t)(uintptr_t)pthread_self(); } +static void proc_counters(uint32_t *faults, uint32_t *io_kb) { + struct rusage ru; + *faults = 0; *io_kb = 0; + if (getrusage(RUSAGE_SELF, &ru) == 0) { + *faults = (uint32_t)(ru.ru_minflt + ru.ru_majflt); + *io_kb = (uint32_t)(ru.ru_inblock / 2); /* 512-byte blocks */ + } +} +#endif + +static _Atomic uint64_t s_origin_us; +static _Atomic uint64_t s_emu_tid; +static _Atomic uint32_t s_cur_frame; + +/* A claimed sequence is not necessarily published yet. Slot ownership protects + * both payload and sequence from concurrent wrap/read/write. Never wait on a + * diagnostic reader: contended samples are dropped and getters skip holes. */ +typedef struct { + _Atomic uint32_t busy; + uint64_t published; + HostSpan value; +} SpanSlot; +static SpanSlot s_spans[HOST_SPAN_RING_CAP]; +static _Atomic uint64_t s_span_seq; + +typedef struct { uint64_t t_us; uint32_t frame; uint32_t interp; uint32_t checks; uint32_t faults; uint32_t io_kb; uint32_t pad; } FrameStamp; +typedef struct { + _Atomic uint32_t busy; + uint64_t published; + FrameStamp value; +} FrameSlot; +static FrameSlot s_frames[HOST_FRAME_STAMP_CAP]; +static _Atomic uint64_t s_frame_seq; + +static int slot_acquire(_Atomic uint32_t *busy) { + uint32_t expected = 0; + return atomic_compare_exchange_strong_explicit(busy, &expected, 1, + memory_order_acquire, memory_order_relaxed); +} + +static void slot_release(_Atomic uint32_t *busy) { + atomic_store_explicit(busy, 0, memory_order_release); +} + +uint64_t host_clock_us(void) { + uint64_t now = qpc_now_us(); + uint64_t origin = atomic_load_explicit(&s_origin_us, memory_order_relaxed); + if (!origin) { + uint64_t expect = 0; + /* First caller fixes the origin; "now | 1" keeps "unset" (0) distinguishable. */ + uint64_t mine = now ? now : 1; + if (atomic_compare_exchange_strong(&s_origin_us, &expect, mine)) + origin = mine; + else + origin = expect; + } + return now >= origin ? now - origin : 0; +} + +uint64_t host_span_begin(void) { return host_clock_us(); } + +void host_span_record(HostSpanKind kind, uint64_t t0_us, uint64_t dur_us, uint32_t arg) { + if (dur_us < HOST_SPAN_MIN_US) return; + uint64_t n = atomic_fetch_add_explicit(&s_span_seq, 1, memory_order_relaxed); + SpanSlot *slot = &s_spans[n % HOST_SPAN_RING_CAP]; + if (!slot_acquire(&slot->busy)) return; + /* A suspended older writer must not replace a newer lap of this slot. */ + if (slot->published > n) { slot_release(&slot->busy); return; } + HostSpan *s = &slot->value; + s->t0_us = t0_us; + s->dur_us = dur_us > 0xFFFFFFFFull ? 0xFFFFFFFFu : (uint32_t)dur_us; + s->frame = atomic_load_explicit(&s_cur_frame, memory_order_relaxed); + s->arg = arg; + s->kind = (uint16_t)kind; + s->emu = this_thread_id() == atomic_load_explicit(&s_emu_tid, memory_order_relaxed); + slot->published = n + 1; + slot_release(&slot->busy); +} + +void host_span_end(HostSpanKind kind, uint64_t t0_us, uint32_t arg) { + uint64_t now = host_clock_us(); + host_span_record(kind, t0_us, now >= t0_us ? now - t0_us : 0, arg); +} + +uint64_t host_span_total(void) { return atomic_load_explicit(&s_span_seq, memory_order_relaxed); } + +int host_span_get(uint64_t seq, HostSpan *out) { + uint64_t total = host_span_total(); + if (!out || seq >= total || total - seq > HOST_SPAN_RING_CAP) return 0; + SpanSlot *slot = &s_spans[seq % HOST_SPAN_RING_CAP]; + if (!slot_acquire(&slot->busy)) return 0; + const int ready = slot->published == seq + 1; + if (ready) *out = slot->value; + slot_release(&slot->busy); + return ready; +} + +const char *host_span_kind_name(unsigned kind) { + static const char *const names[HSPAN_KIND_COUNT] = { + "none", "autocapture_tick", "provider_poll", "publish_commit", "loader_rescan", + "dll_register", "lazy_load", "capture_on_dma", "capture_before_dma", "ac_request", "ac_done_join", + "ac_prepare_image", "ac_child", "overlay_dispatch", "mod_work", "frame_present", "disc_read", + }; + return kind < HSPAN_KIND_COUNT ? names[kind] : "?"; +} + +void host_frame_stamp(uint32_t frame, uint32_t interp_insns, uint32_t static_checks) { + atomic_store_explicit(&s_emu_tid, this_thread_id(), memory_order_relaxed); + atomic_store_explicit(&s_cur_frame, frame, memory_order_relaxed); + uint64_t n = atomic_fetch_add_explicit(&s_frame_seq, 1, memory_order_relaxed); + FrameSlot *slot = &s_frames[n % HOST_FRAME_STAMP_CAP]; + if (!slot_acquire(&slot->busy)) return; + if (slot->published > n) { slot_release(&slot->busy); return; } + FrameStamp *f = &slot->value; + f->t_us = host_clock_us(); + f->frame = frame; + f->interp = interp_insns; + f->checks = static_checks; + proc_counters(&f->faults, &f->io_kb); + slot->published = n + 1; + slot_release(&slot->busy); +} + +uint64_t host_frame_stamp_total(void) { return atomic_load_explicit(&s_frame_seq, memory_order_relaxed); } + +int host_frame_stamp_get(uint64_t seq, uint32_t *frame, uint64_t *t_us, uint32_t *interp_insns, + uint32_t *static_checks, uint32_t *page_faults, uint32_t *io_read_kb) { + uint64_t total = host_frame_stamp_total(); + if (seq >= total || total - seq > HOST_FRAME_STAMP_CAP) return 0; + FrameSlot *slot = &s_frames[seq % HOST_FRAME_STAMP_CAP]; + if (!slot_acquire(&slot->busy)) return 0; + if (slot->published != seq + 1) { slot_release(&slot->busy); return 0; } + const FrameStamp *f = &slot->value; + if (frame) *frame = f->frame; + if (t_us) *t_us = f->t_us; + if (interp_insns) *interp_insns = f->interp; + if (static_checks) *static_checks = f->checks; + if (page_faults) *page_faults = f->faults; + if (io_read_kb) *io_read_kb = f->io_kb; + slot_release(&slot->busy); + return 1; +} diff --git a/runtime/src/iso_reader_c.cpp b/runtime/src/iso_reader_c.cpp index 78c63ba6..f26415c9 100644 --- a/runtime/src/iso_reader_c.cpp +++ b/runtime/src/iso_reader_c.cpp @@ -4,6 +4,7 @@ * Provides iso_open() / iso_read_sector() / iso_close() for use by cdrom.c */ +#include "host_span_ring.h" #include "iso_reader.h" #include "mod_runtime.h" #include @@ -23,7 +24,10 @@ void* iso_open(const char* path) { int iso_read_sector(void* handle, uint32_t lba, uint8_t* buffer, int size) { if (!handle || !buffer || size < 2048) return 0; auto* reader = static_cast(handle); - if (!mod_runtime_read_disc_extent(lba, 0, buffer, size) && !reader->ReadSector(lba, buffer)) return 0; + const uint64_t span_t0 = host_span_begin(); + const bool read_ok = mod_runtime_read_disc_extent(lba, 0, buffer, size) || reader->ReadSector(lba, buffer); + host_span_end(HSPAN_DISC_READ, span_t0, lba); /* a stalled disk shows here, not as an unexplained frame */ + if (!read_ok) return 0; mod_runtime_patch_disc_sector(lba, 0, buffer, 2048); return 1; } @@ -31,7 +35,10 @@ int iso_read_sector(void* handle, uint32_t lba, uint8_t* buffer, int size) { int iso_read_raw_sector(void* handle, uint32_t lba, uint8_t* buffer, int size) { if (!handle || !buffer || size < 2352) return 0; auto* reader = static_cast(handle); - if (!mod_runtime_read_disc_extent(lba, 1, buffer, size) && !reader->ReadRawSector(lba, buffer)) return 0; + const uint64_t span_t0 = host_span_begin(); + const bool read_ok = mod_runtime_read_disc_extent(lba, 1, buffer, size) || reader->ReadRawSector(lba, buffer); + host_span_end(HSPAN_DISC_READ, span_t0, lba); + if (!read_ok) return 0; mod_runtime_patch_disc_sector(lba, 1, buffer, 2352); return 1; } diff --git a/runtime/src/main.cpp b/runtime/src/main.cpp index 836cb244..cca6e711 100644 --- a/runtime/src/main.cpp +++ b/runtime/src/main.cpp @@ -45,6 +45,10 @@ #include "overlay_loader.h" #include "autocompile.h" #include "code_provider.h" +#include "host_span_ring.h" +#ifdef PSX_HAS_OVERLAY_DISPATCH +extern "C" void psx_overlay_static_get_stats(uint64_t *, uint64_t *, uint64_t *, uint64_t *); +#endif extern "C" void psx_event_step_conservative_env_init(void); /* memory.c's last-word-store record for the idle-loop detector. */ extern "C" int g_psx_track_last_store; @@ -8804,6 +8808,17 @@ static NetplayVblankEpilogue sdl_vblank_present_body(void) { int override = -1; int override_p2 = -1; #endif + /* Always-on wall-time stamp for this guest frame (host_span_ring.h). */ + extern uint64_t s_frame_count; + uint32_t stamp_static_checks = 0; +#ifdef PSX_HAS_OVERLAY_DISPATCH + { + uint64_t sc = 0, sh = 0, sv = 0, sa = 0; + psx_overlay_static_get_stats(&sc, &sh, &sv, &sa); + stamp_static_checks = (uint32_t)sc; + } +#endif + host_frame_stamp((uint32_t)s_frame_count, (uint32_t)g_dirty_ram_insns_run, stamp_static_checks); psx_local_mouse_begin(sdl_window, local_mouse_live(override)); { @@ -8913,7 +8928,9 @@ static NetplayVblankEpilogue sdl_vblank_present_body(void) { * frontend is skipping presents. Both are cheap and emu-thread-only. */ { uint64_t perf_start = runtime_perf_section_begin(); + const uint64_t span_t0 = host_span_begin(); overlay_autocapture_tick(); + host_span_end(HSPAN_AUTOCAPTURE_TICK, span_t0, 0); runtime_perf_section_end(perf_start, &g_runtime_perf.autocapture_ticks); } @@ -8921,7 +8938,9 @@ static NetplayVblankEpilogue sdl_vblank_present_body(void) { * cache rescan on done). */ uint64_t perf_start = runtime_perf_section_begin(); const CodeProvider *cp = code_provider_active(); + const uint64_t span_t0 = host_span_begin(); if (cp->poll_main) cp->poll_main(); + host_span_end(HSPAN_PROVIDER_POLL, span_t0, 0); runtime_perf_section_end(perf_start, &g_runtime_perf.provider_poll_ticks); } @@ -18587,7 +18606,19 @@ int main(int argc, char** argv) { const char *tk_recompiler = "psxrecomp-game"; const char *tk_tcc = "tcc"; #endif - const bool tk_present = std::filesystem::exists(tk_py); + bool tk_present = std::filesystem::exists(tk_py); + /* A toolchain staged from a different emitter than this runtime writes shards under its + * own codegen hash, a cache directory the loader never reads (LoD playtest 2026-10-12: + * 27 compile runs, no shard ever loaded, everything interpreted). Refuse it loudly: + * autocompile_status reports degraded_reason. An explicit overlay_autocompile_cmd in the + * game config, or PSX_OVERLAY_AUTOCOMPILE_CMD, is the author's own choice and stays, and + * PSX_OVERLAY_ALLOW_STALE_TOOLCHAIN=1 reproduces the stale-toolchain condition on purpose + * (A/B measurements). */ + const char *allow_stale_tk = std::getenv("PSX_OVERLAY_ALLOW_STALE_TOOLCHAIN"); + if (tk_present && !(allow_stale_tk && allow_stale_tk[0] && allow_stale_tk[0] != '0') && + !autocompile_check_toolchain_hash((tk_dir / "include").string().c_str(), + (uint32_t)overlay_loader_codegen_hash())) + tk_present = false; /* Wave-5 F2: the CLI names the compiler it already has (the wizard's pack on * Windows, the native cc on POSIX) in overlay_toolchain/compiler.txt, so a player * with nothing on PATH still gets optimised shards instead of tcc's. */ diff --git a/runtime/src/overlay_capture.c b/runtime/src/overlay_capture.c index cb17790b..47058014 100644 --- a/runtime/src/overlay_capture.c +++ b/runtime/src/overlay_capture.c @@ -1,5 +1,6 @@ #include "overlay_capture.h" #include "overlay_loader.h" +#include "host_span_ring.h" #include "dirty_ram_interp.h" #include "code_provider.h" #include "crc32.h" @@ -257,8 +258,18 @@ void overlay_capture_configure_history(int enabled, const char *persist_dir, } } +static void overlay_capture_on_dma_impl(uint32_t load_addr, uint32_t size, + const uint8_t *bytes); void overlay_capture_on_dma(uint32_t load_addr, uint32_t size, const uint8_t *bytes) +{ + const uint64_t span_t0 = host_span_begin(); + overlay_capture_on_dma_impl(load_addr, size, bytes); + host_span_end(HSPAN_CAPTURE_ON_DMA, span_t0, load_addr); +} + +static void overlay_capture_on_dma_impl(uint32_t load_addr, uint32_t size, + const uint8_t *bytes) { int i; OvEntry *e; @@ -891,7 +902,15 @@ void overlay_capture_write_json(void) 0, psx_ram_live_bytes(), 0); } +static void overlay_capture_before_dma_impl(uint32_t load_addr, uint32_t size); void overlay_capture_before_dma(uint32_t load_addr, uint32_t size) +{ + const uint64_t span_t0 = host_span_begin(); + overlay_capture_before_dma_impl(load_addr, size); + host_span_end(HSPAN_CAPTURE_BEFORE_DMA, span_t0, load_addr); +} + +static void overlay_capture_before_dma_impl(uint32_t load_addr, uint32_t size) { if (!s_enabled || !s_active || size == 0) return; uint32_t lo = psx_ram_canonical_offset(load_addr); diff --git a/runtime/src/overlay_loader.c b/runtime/src/overlay_loader.c index bceb61d9..8427c61d 100644 --- a/runtime/src/overlay_loader.c +++ b/runtime/src/overlay_loader.c @@ -9,6 +9,7 @@ #include "debug_server.h" #include "psx_cycles.h" #include "overlay_unit_defer.h" +#include "host_span_ring.h" /* Out-of-line copy of the header-inline CPU charge for the overlay callback * table: overlay DLLs publish their accumulated CPU charge here, into the @@ -3202,12 +3203,16 @@ void overlay_loader_resync_validation_after_restore(void) * and clear the checked-regions memo so the next dispatch into a window * region reconsiders the cache. Already-loaded DLLs stay loaded; * dll_already_loaded() makes the re-walk idempotent. */ +unsigned overlay_loader_codegen_hash(void) { return (unsigned)PSX_OVERLAY_CODEGEN_HASH; } + void overlay_loader_rescan(void) { if (!s_active || !overlay_loads_allowed()) return; + const uint64_t span_t0 = host_span_begin(); scan_cache_dir(); load_bios_resident_shards(); s_nchecked = 0; lazy_miss_invalidate_loader(); + host_span_end(HSPAN_LOADER_RESCAN, span_t0, (uint32_t)s_cache_idx_count); } /* Loaded-DLL set — the cache is ADDITIVE: a memory slot reused by several @@ -3275,8 +3280,8 @@ static void overlay_library_close(OverlayLibraryHandle handle) { /* Consumes prepared on every path. A successful registration intentionally * retains that reference for process lifetime, matching the ordinary loader. */ -static int load_one_dll(const char *dll_path, - OverlayLibraryHandle prepared) { +static int load_one_dll_impl(const char *dll_path, + OverlayLibraryHandle prepared) { /* Fail CLOSED at the tracking cap, BEFORE registering anything: past this * point dll_already_loaded() would lose track of the DLL and a later * rescan could double-register its candidates (stale-chain execution). @@ -3377,6 +3382,15 @@ static int load_one_dll(const char *dll_path, return registered; } +/* Every register-a-shard load, whichever path asked (rescan, lazy miss, + * published image), is one wall-time span in the always-on host_span_ring. */ +static int load_one_dll(const char *dll_path, OverlayLibraryHandle prepared) { + const uint64_t span_t0 = host_span_begin(); + int registered = load_one_dll_impl(dll_path, prepared); + host_span_end(HSPAN_DLL_REGISTER, span_t0, (uint32_t)registered); + return registered; +} + static int load_one_dll_prepared(const char *dll_path, OverlayLibraryHandle prepared) { /* load_one_dll performs lazy_miss_invalidate_loader(); keep this wrapper @@ -3465,7 +3479,15 @@ OverlayPreparedImage *overlay_loader_prepare_published(const char *dll_path) { return image; } +static int overlay_loader_commit_published_impl(OverlayPreparedImage *image); int overlay_loader_commit_published(OverlayPreparedImage *image) { + const uint64_t span_t0 = host_span_begin(); + int loaded = overlay_loader_commit_published_impl(image); + host_span_end(HSPAN_PUBLISH_COMMIT, span_t0, (uint32_t)loaded); + return loaded; +} + +static int overlay_loader_commit_published_impl(OverlayPreparedImage *image) { if (!image) return 0; if (!overlay_loads_allowed()) { overlay_loader_discard_prepared(image); @@ -3637,7 +3659,16 @@ static int lazy_load_selected(int li) { /* Load the cached shard of `seg` (§5.7) that serves phys. The region walkback * and the manifest indexes are physical: the bytes, and so the region, are the * same in every segment. lazy_is_loadable() admits only `seg`'s manifests. */ +static int try_load_region_impl(uint32_t seg, uint32_t phys); static int try_load_region(uint32_t seg, uint32_t phys) { + const uint64_t span_t0 = host_span_begin(); + int loaded = try_load_region_impl(seg, phys); + host_span_end(HSPAN_LAZY_LOAD, span_t0, phys); + (void)loaded; + return loaded; +} + +static int try_load_region_impl(uint32_t seg, uint32_t phys) { extern uint32_t dirty_ram_get_bitmap_word(uint32_t word_index); if (!overlay_loads_allowed()) diff --git a/runtime/tests/test_autocompile_toolchain_hash.c b/runtime/tests/test_autocompile_toolchain_hash.c new file mode 100644 index 00000000..2d6d4838 --- /dev/null +++ b/runtime/tests/test_autocompile_toolchain_hash.c @@ -0,0 +1,68 @@ +/* A staged overlay toolchain from a different emitter than the runtime writes shards under its + * own codegen hash (a cache directory the runtime never reads). autocompile_check_toolchain_hash + * must refuse it loudly (degraded_reason), accept a matching one, and stay quiet when the header + * is absent or unparseable. Build/run: ctest -R autocompile_toolchain_hash_test */ +#include "autocompile.h" +#include "overlay_loader.h" + +#define WIN32_LEAN_AND_MEAN +#include + +#include +#include +#include + +struct OverlayPreparedImage { unsigned id; }; +OverlayPreparedImage *overlay_loader_prepare_published(const char *p) { (void)p; return NULL; } +int overlay_loader_commit_published(OverlayPreparedImage *i) { (void)i; return 0; } +void overlay_loader_discard_prepared(OverlayPreparedImage *i) { (void)i; } +void overlay_loader_rescan(void) {} + +static int failures; +#define CHECK(c) do { if (!(c)) { printf("FAIL %s:%d %s\n", __FILE__, __LINE__, #c); failures++; } } while (0) + +static void write_header(const char *dir, const char *body) { + char path[600]; + snprintf(path, sizeof path, "%s/overlay_codegen_hash.h", dir); + FILE *f = fopen(path, "wb"); + if (f) { fputs(body, f); fclose(f); } +} + +int main(void) { + char dir[MAX_PATH]; + GetTempPathA(sizeof dir, dir); + strcat(dir, "psx_ac_tkhash_test"); + CreateDirectoryA(dir, NULL); + + /* No header: unknown -> usable, nothing recorded. */ + char missing[MAX_PATH + 16]; + snprintf(missing, sizeof missing, "%s/nope", dir); + CHECK(autocompile_check_toolchain_hash(missing, 0xBA11DD86u) == 1); + CHECK(autocompile_degraded_reason() == NULL); + + /* Unparseable header and runtime hash 0 (unknown build): usable. */ + write_header(dir, "// nothing here\n"); + CHECK(autocompile_check_toolchain_hash(dir, 0xBA11DD86u) == 1); + write_header(dir, "#define PSX_OVERLAY_CODEGEN_HASH 0x0bea7895u\n"); + CHECK(autocompile_check_toolchain_hash(dir, 0u) == 1); + CHECK(autocompile_degraded_reason() == NULL); + + /* Matching hash: usable. */ + write_header(dir, "#pragma once\n#define PSX_OVERLAY_CODEGEN_HASH 0xba11dd86u\n"); + CHECK(autocompile_check_toolchain_hash(dir, 0xBA11DD86u) == 1); + CHECK(autocompile_degraded_reason() == NULL); + + /* The 2026-10-12 playtest case: toolchain from an older emitter. */ + write_header(dir, "#pragma once\n#define PSX_OVERLAY_CODEGEN_HASH 0x0bea7895u\n"); + CHECK(autocompile_check_toolchain_hash(dir, 0xBA11DD86u) == 0); + const char *why = autocompile_degraded_reason(); + CHECK(why != NULL); + CHECK(why && strstr(why, "0x0bea7895") && strstr(why, "0xba11dd86") && strstr(why, "stale overlay toolchain")); + char json[4096]; + autocompile_status_json(json, (int)sizeof json); + CHECK(strstr(json, "\"degraded\":1") != NULL); + + if (failures) { printf("%d failure(s)\n", failures); return 1; } + printf("autocompile_toolchain_hash_test: ok\n"); + return 0; +} diff --git a/runtime/tests/test_compile_overlays_publish_marker.py b/runtime/tests/test_compile_overlays_publish_marker.py new file mode 100644 index 00000000..ba63a605 --- /dev/null +++ b/runtime/tests/test_compile_overlays_publish_marker.py @@ -0,0 +1,40 @@ +#!/usr/bin/env python3 +"""publish_shard_pair announces each committed shard as `PSX_SHARD_PUBLISHED ` -- but only to a +runtime that asked (PSX_OVERLAY_LIVE_AUTOCOMPILE=1). The runtime's publication pipeline +(autocompile.c) consumes the line; without it every shard compiled during play is first mapped by +the emulation thread (300 ms LoadLibrary at the first dispatch miss, measured).""" +import contextlib, importlib.util, io, os, sys, tempfile +from pathlib import Path + +root = Path(__file__).resolve().parents[2] +spec = importlib.util.spec_from_file_location('compile_overlays', root / 'tools' / 'compile_overlays.py') +co = importlib.util.module_from_spec(spec) +sys.modules['compile_overlays'] = co +sys.path.insert(0, str(root / 'tools')) +spec.loader.exec_module(co) + + +def run(live): + if live: + os.environ['PSX_OVERLAY_LIVE_AUTOCOMPILE'] = '1' + else: + os.environ.pop('PSX_OVERLAY_LIVE_AUTOCOMPILE', None) + buf = io.StringIO() + with contextlib.redirect_stdout(buf): + co.announce_published_shard(str(Path(tempfile.gettempdir()) / '00012000_DEADBEEF.dll')) + return buf.getvalue() + + +quiet = run(False) +assert quiet == '', f'offline compile must keep stdout quiet, got {quiet!r}' +loud = run(True) +line = loud.strip() +assert line.startswith('PSX_SHARD_PUBLISHED '), loud +assert line.endswith('00012000_DEADBEEF.dll'), loud +assert os.path.isabs(line[len('PSX_SHARD_PUBLISHED '):]), 'path must be absolute (runtime resolves it)' +assert loud.count('\n') == 1 +# The announcement sits on the success path of the single commit point. +src = (root / 'tools' / 'compile_overlays.py').read_text(encoding='utf-8') +body = src[src.index('def publish_shard_pair('):src.index('def _dll_abi_matches(')] +assert 'announce_published_shard(dll)' in body and body.index('announce_published_shard(dll)') > body.index('os.replace(staged_dll, dll)') +print('publish marker: ok') diff --git a/runtime/tests/test_host_span_ring.c b/runtime/tests/test_host_span_ring.c new file mode 100644 index 00000000..cd59165d --- /dev/null +++ b/runtime/tests/test_host_span_ring.c @@ -0,0 +1,129 @@ +/* test_host_span_ring.c - the always-on wall-time rings (host_span_ring.h): + * span filter, emulation-thread attribution, ring wrap, frame stamps. */ +#include "host_span_ring.h" + +#include +#include +#include + +static _Atomic unsigned writers_done; +static void race_write(void) { + for (unsigned i = 1; i <= HOST_SPAN_RING_CAP * 3u; ++i) + host_span_record(HSPAN_DISC_READ, (uint64_t)i * 1000u, 50u + i, i); + atomic_fetch_add(&writers_done, 1u); +} + +#ifdef _WIN32 +#include +static void sleep_ms(unsigned ms) { Sleep(ms); } +typedef HANDLE Thr; +static DWORD WINAPI bg_main(LPVOID p); +static Thr thr_start(void) { return CreateThread(NULL, 0, bg_main, NULL, 0, NULL); } +static void thr_join(Thr t) { WaitForSingleObject(t, INFINITE); CloseHandle(t); } +static DWORD WINAPI race_main(LPVOID p) { (void)p; race_write(); return 0; } +static Thr race_start(void) { return CreateThread(NULL, 0, race_main, NULL, 0, NULL); } +static DWORD WINAPI bg_main(LPVOID p) { + (void)p; + uint64_t t0 = host_span_begin(); + sleep_ms(3); + host_span_end(HSPAN_AC_CHILD, t0, 7); + return 0; +} +#else +#include +#include +static void sleep_ms(unsigned ms) { usleep(ms * 1000u); } +typedef pthread_t Thr; +static void *bg_main(void *p) { + (void)p; + uint64_t t0 = host_span_begin(); + sleep_ms(3); + host_span_end(HSPAN_AC_CHILD, t0, 7); + return NULL; +} +static Thr thr_start(void) { pthread_t t; pthread_create(&t, NULL, bg_main, NULL); return t; } +static void thr_join(Thr t) { pthread_join(t, NULL); } +static void *race_main(void *p) { (void)p; race_write(); return NULL; } +static Thr race_start(void) { pthread_t t; pthread_create(&t, NULL, race_main, NULL); return t; } +#endif + +static int failures; +#define CHECK(c) do { if (!(c)) { printf("FAIL %s:%d %s\n", __FILE__, __LINE__, #c); failures++; } } while (0) + +int main(void) { + /* Frame stamps: monotonic, carry frame number and interpreter count. */ + host_frame_stamp(100, 11, 5); + sleep_ms(2); + host_frame_stamp(101, 25, 9); + CHECK(host_frame_stamp_total() == 2); + uint32_t fr = 0, ii = 0, ck = 0, pf = 0, io = 0; uint64_t t_a = 0, t_b = 0; + CHECK(host_frame_stamp_get(0, &fr, &t_a, &ii, &ck, &pf, &io) && fr == 100 && ii == 11 && ck == 5); + CHECK(host_frame_stamp_get(1, &fr, &t_b, &ii, &ck, &pf, &io) && fr == 101 && ii == 25 && ck == 9); + CHECK(t_b >= t_a + 1500); /* ~2 ms apart */ + CHECK(!host_frame_stamp_get(2, &fr, &t_a, &ii, &ck, &pf, &io)); /* not written yet */ + + /* A span shorter than HOST_SPAN_MIN_US is dropped; a long one is kept and tagged emu. */ + uint64_t s0 = host_span_total(); + host_span_record(HSPAN_PROVIDER_POLL, host_clock_us(), HOST_SPAN_MIN_US - 1, 1); + CHECK(host_span_total() == s0); + uint64_t t0 = host_span_begin(); + sleep_ms(2); + host_span_end(HSPAN_LOADER_RESCAN, t0, 42); + CHECK(host_span_total() == s0 + 1); + HostSpan sp; + CHECK(host_span_get(s0, &sp)); + CHECK(sp.kind == HSPAN_LOADER_RESCAN && sp.arg == 42 && sp.emu == 1 && sp.frame == 101); + CHECK(sp.dur_us >= 1500 && sp.t0_us == t0); + + /* A span from another thread is attributed to the background. */ + Thr t = thr_start(); + thr_join(t); + CHECK(host_span_total() == s0 + 2); + CHECK(host_span_get(s0 + 1, &sp)); + CHECK(sp.kind == HSPAN_AC_CHILD && sp.emu == 0 && sp.arg == 7); + + /* Ring wrap: old sequence numbers age out, newest are readable. */ + for (unsigned i = 0; i < HOST_SPAN_RING_CAP + 10; i++) + host_span_record(HSPAN_MOD_WORK, 1000 + i, 100, i); + uint64_t total = host_span_total(); + CHECK(!host_span_get(s0, &sp)); /* evicted */ + CHECK(host_span_get(total - 1, &sp) && sp.arg == HOST_SPAN_RING_CAP + 9); + CHECK(host_span_get(total - HOST_SPAN_RING_CAP, &sp)); /* oldest still held */ + CHECK(!host_span_get(total, &sp)); + + CHECK(host_span_kind_name(HSPAN_PUBLISH_COMMIT)[0] == 'p'); + CHECK(host_span_kind_name(9999)[0] == '?'); + + /* Multiple writers wrap the ring while the emulation thread reads it. + * A row may be unavailable, but an available row must be internally + * consistent; reserving a sequence must not publish stale slot bytes. */ + uint64_t race_begin = host_span_total(), reads = 0; + Thr a = race_start(), b = race_start(); + while (atomic_load(&writers_done) < 2u) { + uint64_t end = host_span_total(); + uint64_t begin = end > 256u ? end - 256u : race_begin; + if (begin < race_begin) begin = race_begin; + for (uint64_t q = begin; q < end; ++q) { + if (!host_span_get(q, &sp)) continue; + CHECK(sp.kind == HSPAN_DISC_READ && sp.emu == 0); + CHECK(sp.t0_us == (uint64_t)sp.arg * 1000u); + CHECK(sp.dur_us == 50u + sp.arg); + ++reads; + } + } + thr_join(a); thr_join(b); + CHECK(reads != 0); + + /* The frame ring wraps independently and preserves every counter. */ + for (unsigned i = 0; i < HOST_FRAME_STAMP_CAP + 2u; ++i) + host_frame_stamp(i + 200u, i * 3u, i * 5u); + total = host_frame_stamp_total(); + CHECK(!host_frame_stamp_get(0, NULL, NULL, NULL, NULL, NULL, NULL)); + CHECK(host_frame_stamp_get(total - 1, &fr, &t_a, &ii, &ck, &pf, &io)); + CHECK(fr == HOST_FRAME_STAMP_CAP + 201u); + CHECK(ii == (HOST_FRAME_STAMP_CAP + 1u) * 3u && ck == (HOST_FRAME_STAMP_CAP + 1u) * 5u); + + if (failures) { printf("%d failure(s)\n", failures); return 1; } + printf("host_span_ring_test: ok\n"); + return 0; +} diff --git a/tools/compile_overlays.py b/tools/compile_overlays.py index 298e4d65..ad363d5c 100644 --- a/tools/compile_overlays.py +++ b/tools/compile_overlays.py @@ -7095,6 +7095,22 @@ def _runtime_valid_shard_pair_locked(dll: str, ranges: str, {entry for entry, _crc, _ranges in funcs})) +def announce_published_shard(dll: str) -> None: + """Tell a live runtime that `dll` (with its .ranges) is committed and loadable. + + The runtime's autocompile pipeline (runtime/src/autocompile.c) maps each announced + shard on a worker thread while the compiler is still running and commits it between + frames. Without this line every shard compiled during play is first mapped by the + EMULATION thread at its first dispatch miss: a synchronous LoadLibrary (measured + 300 ms on a cold Windows file, antivirus included) plus the batch-end cache rescan. + Only a runtime that asked for it (PSX_OVERLAY_LIVE_AUTOCOMPILE=1, set by + autocompile_request) receives the line; offline builds keep a quiet stdout. + """ + if os.environ.get('PSX_OVERLAY_LIVE_AUTOCOMPILE') != '1': + return + print(f'PSX_SHARD_PUBLISHED {os.path.abspath(dll)}', flush=True) + + def publish_shard_pair(staged_dll: str, staged_ranges: str, final_dll: str, preserve_existing: bool = False, expected_existing_abi: int | None = None, @@ -7181,6 +7197,7 @@ def publish_shard_pair(staged_dll: str, staged_ranges: str, except BaseException: _recover_shard_pair_locked(dll) raise + announce_published_shard(dll) return True