diff --git a/docs/TCP_COMMANDS.md b/docs/TCP_COMMANDS.md index 6090a1d8..fc4441d3 100644 --- a/docs/TCP_COMMANDS.md +++ b/docs/TCP_COMMANDS.md @@ -431,13 +431,42 @@ If an inspection need isn't covered by the existing commands, **do not fall back The TCP server is the canonical instrumentation surface. Rule 3 in `CLAUDE.md` is absolute: **no `fprintf(stderr, …)` in source code, ever, for any reason**. +## `host_launch_timings` — retained host startup and mod-commit costs + +`{"cmd":"host_launch_timings","count":256}` reads the newest completed host +scopes, oldest completion first. The fixed 256-entry ring is always on, including +before TCP starts, and reading it never drains or resets it. `total` is the +lifetime completion count; `overwritten` counts completions displaced by ring +wrap. `count` is clamped to 1..256. Only completed work is represented. + +Each entry has `seq`, `scope_id`, `parent_id`, `stage`, `start_us`, `duration_us`, +`ok`, `package`, `feature`, and `labels_truncated`. Times use a monotonic host +clock, independent of guest frames/cycles. A parent includes its children: +**nested durations overlap and must not be summed**. Sequence orders completion; +scope IDs identify starts. Separate threads have independent parent chains. +Package/feature labels retain at most 63 bytes each; no owner-media paths are +recorded. `ok=0` indicates an unsuccessful or incomplete scope exit, including +exceptions; it is not a replacement for the existing launch error message. + +`provider_commit` encloses the launcher's offline mod callback; +`provider_netplay_commit` identifies its netplay counterpart. `runtime_commit` +encloses the later main-thread commit/clear. Within `commit`, stages distinguish +`disc_hash` (absent when the existing digest is reused), `prepare_resources` +(with nested per-package/feature `media_provider`), `resolve`, `overlay_verify`, +`derived_disc`, `save_state`, and `build_disc_index`. `overlay_worker` records +the concurrent startup work; `overlay_join` measures only the later wait. +`plugin_activation` contains per-package/feature `plugin_callback` measurements, +including Resident Loading when enabled. No work is moved off-thread and no +verification or cache policy changes. These scopes do not cover every action +between Play and TCP availability. + ## Complete command index (generated) -**349 commands registered** — 336 on the native server (`runtime/src/debug_server.c`), 61 on the Beetle server (`runtime/src/beetle_debug_server.c`). +**352 commands registered** — 339 on the native server (`runtime/src/debug_server.c`), 61 on the Beetle server (`runtime/src/beetle_debug_server.c`). -68 of 349 have prose above; **281 are index-only**. An index-only command still works — it just has no description here yet. Send it `{"cmd":""}` and read the reply, or find its `handle_*` function in the server source. +69 of 352 have prose above; **283 are index-only**. An index-only command still works — it just has no description here yet. Send it `{"cmd":""}` and read the reply, or find its `handle_*` function in the server source. Regenerate with `python tools/gen_tcp_commands.py`; `--check` fails if this block has drifted from the code. @@ -587,6 +616,7 @@ Regenerate with `python tools/gen_tcp_commands.py`; `--check` fails if this bloc | `guest_tty_dump` | ✓ | | | | `history` | ✓ | ✓ | ✓ | | `hle_dump` | ✓ | | ✓ | +| `host_launch_timings` | ✓ | | ✓ | | `idle_skip` | ✓ | | | | `imask_trace` | ✓ | | | | `input_route_append` | ✓ | | | @@ -655,6 +685,8 @@ Regenerate with `python tools/gen_tcp_commands.py`; `--check` fails if this bloc | `pgxp` | ✓ | | ✓ | | `pgxp_miss_ring` | ✓ | | | | `pgxp_shadow` | ✓ | | | +| `pgxp_store_ring` | ✓ | | | +| `pgxp_tri_ring` | ✓ | | | | `phase_hot` | ✓ | | | | `phase_profile` | ✓ | | ✓ | | `ping` | ✓ | ✓ | ✓ | diff --git a/runtime/CMakeLists.txt b/runtime/CMakeLists.txt index 2ccf779e..c9ab3bf2 100644 --- a/runtime/CMakeLists.txt +++ b/runtime/CMakeLists.txt @@ -23,6 +23,12 @@ psxrecomp_add_runtime_target(psx-runtime # (docs/ENHANCEMENTS.md G1.10). Titles get their _pgxp the same way. if(BUILD_TESTING) + find_package(Threads REQUIRED) + add_executable(host_launch_timing_test + tests/test_host_launch_timing.cpp tests/host_launch_timing_helper.cpp) + target_include_directories(host_launch_timing_test PRIVATE include) + target_link_libraries(host_launch_timing_test PRIVATE Threads::Threads) + add_test(NAME host_launch_timing_test COMMAND host_launch_timing_test) add_executable(disasm_test tests/test_disasm.cpp src/disasm_shim.cpp ../recompiler/src/mips_decoder.cpp) target_include_directories(disasm_test PRIVATE include ../recompiler/include) @@ -129,6 +135,12 @@ if(BUILD_TESTING) set(PSX_GL_READBACK_COMPILER_BIN "${_gl_test_default_bin}" CACHE PATH "GCC/MinGW bin for GL fixture") find_package(Python3 QUIET COMPONENTS Interpreter) if(Python3_Interpreter_FOUND) + add_test(NAME host_launch_timings_protocol_test COMMAND ${CMAKE_COMMAND} -E env + "CC=${CMAKE_C_COMPILER}" "CXX=${CMAKE_CXX_COMPILER}" "${Python3_EXECUTABLE}" + "${CMAKE_CURRENT_SOURCE_DIR}/tests/test_host_launch_timings_protocol.py") + set_tests_properties(host_launch_timings_protocol_test PROPERTIES SKIP_RETURN_CODE 77) + add_test(NAME tcp_command_index_check COMMAND "${Python3_EXECUTABLE}" + "${PSXRECOMP_ROOT}/tools/gen_tcp_commands.py" --check) add_test(NAME wtrace_dump_test COMMAND ${CMAKE_COMMAND} -E env "CC=${CMAKE_C_COMPILER}" "${Python3_EXECUTABLE}" "${CMAKE_CURRENT_SOURCE_DIR}/tests/test_wtrace_dump.py") diff --git a/runtime/include/host_launch_timing.h b/runtime/include/host_launch_timing.h new file mode 100644 index 00000000..aa6693c6 --- /dev/null +++ b/runtime/include/host_launch_timing.h @@ -0,0 +1,145 @@ +#pragma once + +#include + +/* Always-on host diagnostics. Completed scopes survive startup for the debug + * TCP reader. Nested scopes overlap: do not sum a parent and its children. + * No guest clocks, filesystem paths, logging, or environment switches. */ +#define HOST_LAUNCH_TIMING_CAPACITY 256u +#define HOST_LAUNCH_TIMING_LABEL 64u + +typedef enum HostLaunchStage { + HOST_LAUNCH_PROVIDER_COMMIT, + HOST_LAUNCH_RUNTIME_COMMIT, + HOST_LAUNCH_COMMIT, + HOST_LAUNCH_DISC_HASH, + HOST_LAUNCH_PREPARE_RESOURCES, + HOST_LAUNCH_MEDIA_PROVIDER, + HOST_LAUNCH_RESOLVE, + HOST_LAUNCH_OVERLAY_VERIFY, + HOST_LAUNCH_DERIVED_DISC, + HOST_LAUNCH_SAVE_STATE, + HOST_LAUNCH_BUILD_DISC_INDEX, + HOST_LAUNCH_OVERLAY_WORKER, + HOST_LAUNCH_OVERLAY_JOIN, + HOST_LAUNCH_PLUGIN_ACTIVATION, + HOST_LAUNCH_PLUGIN_CALLBACK, + HOST_LAUNCH_PROVIDER_NETPLAY_COMMIT +} HostLaunchStage; + +typedef struct HostLaunchTimingEvent { + uint64_t seq; /* completion order, starting at 1 */ + uint64_t scope_id; /* unique start identity, independent of seq */ + uint64_t parent_id; /* same-thread enclosing scope, or 0 */ + uint64_t start_us; /* steady-clock epoch, not guest time */ + uint64_t duration_us; + uint32_t stage; + uint32_t ok; /* explicit success; early return/throw = 0 */ + uint32_t labels_truncated; + char package_id[HOST_LAUNCH_TIMING_LABEL]; + char feature_id[HOST_LAUNCH_TIMING_LABEL]; +} HostLaunchTimingEvent; + +#ifdef __cplusplus +extern "C" { +#endif +/* Newest min(cap, retained) completions, oldest first. Null/zero output is a + * metadata query. total is lifetime completed count; overwritten excludes + * additional entries omitted by a reader's smaller cap. Never drains/reset. */ +uint32_t host_launch_timing_snapshot(HostLaunchTimingEvent* out, uint32_t cap, + uint64_t* total, uint64_t* overwritten); +const char* host_launch_timing_stage_name(uint32_t stage); +#ifdef __cplusplus +} + +#include +#include +#include +#include +#include + +namespace PSXRecompV4 { +/* Header-only to keep package-manager fixtures independent of mod runtime. + * The external-linkage inline accessors' local statics have one instance + * across C++ translation units, not one ring per includer. */ +class HostLaunchTimingRing { + std::mutex mutex_; + std::array events_{}; + uint64_t started_ = 0, completed_ = 0; +public: + uint64_t begin() { + std::lock_guard lock(mutex_); + return ++started_; + } + void finish(HostLaunchTimingEvent event) { + std::lock_guard lock(mutex_); + event.seq = ++completed_; + events_[(event.seq - 1) % events_.size()] = event; + } + uint32_t snapshot(HostLaunchTimingEvent* out, uint32_t cap, + uint64_t* total, uint64_t* overwritten) { + std::lock_guard lock(mutex_); + if (total) *total = completed_; + if (overwritten) *overwritten = completed_ > events_.size() + ? completed_ - events_.size() : 0; + if (!out) return 0; + const uint32_t n = static_cast(std::min( + std::min(cap, events_.size()), completed_)); + for (uint32_t i = 0; i < n; ++i) { + const uint64_t seq = completed_ - n + i + 1; + out[i] = events_[(seq - 1) % events_.size()]; + } + return n; + } +}; + +inline HostLaunchTimingRing& host_launch_timing_ring() { + static HostLaunchTimingRing ring; + return ring; +} + +struct HostLaunchTimingParent { HostLaunchTimingRing* ring; uint64_t id; }; +inline HostLaunchTimingParent& host_launch_timing_parent() { + static thread_local HostLaunchTimingParent parent{}; + return parent; +} +inline uint64_t host_launch_now_us() { + return static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()).count()); +} + +class HostLaunchTimingScope { + HostLaunchTimingRing& ring_; + HostLaunchTimingEvent event_{}; + HostLaunchTimingParent previous_; + void label(char* out, const char* text) { + if (!text) return; + const auto size = std::strlen(text); + const auto n = std::min(size, HOST_LAUNCH_TIMING_LABEL - 1u); + std::memcpy(out, text, n); + event_.labels_truncated |= size != n; + } +public: + explicit HostLaunchTimingScope(HostLaunchStage stage, + const char* package = nullptr, const char* feature = nullptr, + HostLaunchTimingRing& ring = host_launch_timing_ring()) + : ring_(ring), previous_(host_launch_timing_parent()) { + event_.scope_id = ring_.begin(); + event_.parent_id = previous_.ring == &ring_ ? previous_.id : 0; + event_.stage = stage; + label(event_.package_id, package); + label(event_.feature_id, feature); + event_.start_us = host_launch_now_us(); + host_launch_timing_parent() = {&ring_, event_.scope_id}; + } + HostLaunchTimingScope(const HostLaunchTimingScope&) = delete; + HostLaunchTimingScope& operator=(const HostLaunchTimingScope&) = delete; + ~HostLaunchTimingScope() { + event_.duration_us = host_launch_now_us() - event_.start_us; + host_launch_timing_parent() = previous_; + ring_.finish(event_); + } + void success() { event_.ok = 1; } +}; +} // namespace PSXRecompV4 +#endif diff --git a/runtime/src/debug_server.c b/runtime/src/debug_server.c index 9d4b592f..b16b757b 100644 --- a/runtime/src/debug_server.c +++ b/runtime/src/debug_server.c @@ -17,6 +17,7 @@ #endif #include #include "debug_server.h" +#include "host_launch_timing.h" #include "psx_video_timing.h" #include "psx_netplay.h" #include "psx_bss.h" @@ -8126,6 +8127,53 @@ static void handle_netplay_status(int id, const char *json) debug_server_send_line(out); } +/* Startup host work recorded before TCP was initialized; always-on, read-only. + * Completion order is not start order. Parents include their children. */ +static void handle_host_launch_timings(int id, const char *json) +{ + int requested = json_get_int(json, "count", HOST_LAUNCH_TIMING_CAPACITY); + if (requested < 1) requested = 1; + if (requested > (int)HOST_LAUNCH_TIMING_CAPACITY) + requested = HOST_LAUNCH_TIMING_CAPACITY; + HostLaunchTimingEvent *events = (HostLaunchTimingEvent *)malloc( + (size_t)requested * sizeof(*events)); + if (!events) { send_err(id, "alloc failed"); return; } + uint64_t total = 0, overwritten = 0; + uint32_t n = host_launch_timing_snapshot(events, (uint32_t)requested, + &total, &overwritten); + /* Two labels may each expand sixfold when JSON-escaped. */ + size_t cap = 512u + (size_t)n * 1536u; + char *buf = (char *)malloc(cap); + if (!buf) { free(events); send_err(id, "alloc failed"); return; } + size_t off = (size_t)snprintf(buf, cap, + "{\"id\":%d,\"ok\":true,\"clock\":\"steady_us\"," + "\"nested_durations_overlap\":true,\"capacity\":%u," + "\"total\":%llu,\"overwritten\":%llu,\"entries\":[", + id, HOST_LAUNCH_TIMING_CAPACITY, (unsigned long long)total, + (unsigned long long)overwritten); + for (uint32_t i = 0; i < n; ++i) { + const HostLaunchTimingEvent *e = &events[i]; + char package[HOST_LAUNCH_TIMING_LABEL * 6u + 1u]; + char feature[HOST_LAUNCH_TIMING_LABEL * 6u + 1u]; + json_escape_string(package, sizeof(package), e->package_id); + json_escape_string(feature, sizeof(feature), e->feature_id); + off += (size_t)snprintf(buf + off, cap - off, + "%s{\"seq\":%llu,\"scope_id\":%llu,\"parent_id\":%llu," + "\"stage\":\"%s\",\"start_us\":%llu,\"duration_us\":%llu," + "\"ok\":%u,\"package\":\"%s\",\"feature\":\"%s\"," + "\"labels_truncated\":%u}", + i ? "," : "", (unsigned long long)e->seq, + (unsigned long long)e->scope_id, (unsigned long long)e->parent_id, + host_launch_timing_stage_name(e->stage), + (unsigned long long)e->start_us, (unsigned long long)e->duration_us, + e->ok, package, feature, e->labels_truncated); + } + snprintf(buf + off, cap - off, "]}"); + debug_server_send_line(buf); + free(buf); + free(events); +} + static void handle_mod_counters(int id, const char *json) { extern int psx_mod_counters_snapshot(const char **names, uint64_t *counts, @@ -15223,6 +15271,7 @@ static const CmdEntry s_commands[] = { { "ws_hud_mode", handle_ws_hud_mode }, { "ws_tag_stats", handle_ws_tag_stats }, { "mod_counters", handle_mod_counters }, + { "host_launch_timings", handle_host_launch_timings }, { "resident_status", handle_resident_status }, { "netplay_status", handle_netplay_status }, { "resident_events", handle_resident_events }, diff --git a/runtime/src/main.cpp b/runtime/src/main.cpp index aa219a89..dfe143c7 100644 --- a/runtime/src/main.cpp +++ b/runtime/src/main.cpp @@ -101,6 +101,7 @@ extern "C" void psx_event_step_conservative_env_init(void); #include "mod_plugins.h" #include "mod_session_baseline.h" #include "mod_runtime.h" +#include "host_launch_timing.h" #include "mod_packages.h" #include "present_image_ring.h" #include "gpu_timeline.h" @@ -15438,6 +15439,7 @@ int main(int argc, char** argv) { std::thread overlay_init_thread; std::exception_ptr overlay_init_exc; auto run_deferred_overlay_init = [&]() { + PSXRecompV4::HostLaunchTimingScope timing(HOST_LAUNCH_OVERLAY_WORKER); std::filesystem::path exe_dir = exe_dir_from_argv(argv[0]); std::string cache_dir = (exe_dir / "cache").string(); std::filesystem::path captures_path = @@ -15623,6 +15625,7 @@ int main(int argc, char** argv) { captures_path.string().c_str()); } code_provider_init(cfg_backend, gcc_avail); + timing.success(); }; if (deferred_overlay_cache) { @@ -16589,6 +16592,7 @@ int main(int argc, char** argv) { #endif if (overlay_init_thread.joinable()) { + PSXRecompV4::HostLaunchTimingScope timing(HOST_LAUNCH_OVERLAY_JOIN); overlay_init_thread.join(); if (overlay_init_exc) { try { @@ -16599,6 +16603,7 @@ int main(int argc, char** argv) { return 1; } } + timing.success(); } if (game_config_path || disc_override_path || !resolved_disc.empty()) { @@ -16614,6 +16619,7 @@ int main(int argc, char** argv) { /* Netplay is vanilla unless the title opted into content negotiation * ([netplay] content_negotiation); either way the user's persisted * offline mod selection is left untouched. */ + PSXRecompV4::HostLaunchTimingScope timing(HOST_LAUNCH_RUNTIME_COMMIT); std::string mod_error; if (net_cfg.enabled) { if (!netplay_commit_mods(resolved_disc, &mod_error)) { @@ -16629,6 +16635,7 @@ int main(int argc, char** argv) { mod_error.c_str()); return 1; } + timing.success(); } /* Session start: every session runs this after its mod commit or netplay * clear -- the first boot here, and the lobby rematch, which re-enters at @@ -18750,6 +18757,7 @@ soft_return_lobby: } } { + PSXRecompV4::HostLaunchTimingScope timing(HOST_LAUNCH_RUNTIME_COMMIT); std::string mod_error; if (net_cfg.enabled) { if (!netplay_commit_mods(resolved_disc, &mod_error)) { @@ -18769,6 +18777,7 @@ soft_return_lobby: SDL_Quit(); return 1; } + timing.success(); } /* `goto session_reboot` re-enters below the first-boot session * block, so run the same session start here, after the diff --git a/runtime/src/mod_packages.cpp b/runtime/src/mod_packages.cpp index bbd68238..98a16a7c 100644 --- a/runtime/src/mod_packages.cpp +++ b/runtime/src/mod_packages.cpp @@ -1,4 +1,5 @@ #include "mod_packages.h" +#include "host_launch_timing.h" #include "crc32.h" #include "mod_plugins.h" @@ -3452,8 +3453,13 @@ bool ModPackageManager::prepare_resources(const std::string& game_id, } std::map outputs; std::string reason; - if (!provider->second(context, outputs, reason)) - throw std::runtime_error(package->name + ": " + reason); + { + HostLaunchTimingScope timing(HOST_LAUNCH_MEDIA_PROVIDER, + package->id.c_str(), feature.id.c_str()); + if (!provider->second(context, outputs, reason)) + throw std::runtime_error(package->name + ": " + reason); + timing.success(); + } for (const auto& [name, path] : outputs) { const auto* resource = find_resource(*package, feature.id, name); if (!resource || resource->input_only || resource->sha256.empty()) diff --git a/runtime/src/mod_runtime.cpp b/runtime/src/mod_runtime.cpp index 8efa62b1..1f82af38 100644 --- a/runtime/src/mod_runtime.cpp +++ b/runtime/src/mod_runtime.cpp @@ -1,4 +1,5 @@ #include "mod_runtime.h" +#include "host_launch_timing.h" #include "cpu_state.h" #include "disc_path.h" @@ -13,6 +14,22 @@ #include "cpu_state.h" #include "psx_lobby_client.h" +extern "C" uint32_t host_launch_timing_snapshot(HostLaunchTimingEvent* out, + uint32_t cap, uint64_t* total, uint64_t* overwritten) { + return PSXRecompV4::host_launch_timing_ring().snapshot(out, cap, total, overwritten); +} + +extern "C" const char* host_launch_timing_stage_name(uint32_t stage) { + static const char* const names[] = { + "provider_commit", "runtime_commit", "commit", "disc_hash", + "prepare_resources", "media_provider", "resolve", "overlay_verify", + "derived_disc", "save_state", "build_disc_index", "overlay_worker", + "overlay_join", "plugin_activation", "plugin_callback", + "provider_netplay_commit" + }; + return stage < sizeof(names) / sizeof(names[0]) ? names[stage] : "unknown"; +} + #if defined(RECOMP_LAUNCHER) #include "recomp_launcher.h" #endif @@ -1165,6 +1182,7 @@ int provider_set_option(void*, const char* id, const char* option, const char* v } int provider_commit(void*, const char* image_path) { + HostLaunchTimingScope timing(HOST_LAUNCH_PROVIDER_COMMIT); std::string error; if (!mod_runtime_commit(image_path ? std::filesystem::path(image_path) : std::filesystem::path(), &error)) { @@ -1172,10 +1190,12 @@ int provider_commit(void*, const char* image_path) { return 0; } state().error.clear(); + timing.success(); return 1; } int provider_commit_netplay(void*, const char* image_path) { + HostLaunchTimingScope timing(HOST_LAUNCH_PROVIDER_NETPLAY_COMMIT); std::string error; /* Without [netplay] content_negotiation every netplay session is vanilla. */ if (!(mod_runtime_netplay_content_negotiation() @@ -1186,6 +1206,7 @@ int provider_commit_netplay(void*, const char* image_path) { return 0; } state().error.clear(); + timing.success(); return 1; } @@ -1569,8 +1590,9 @@ static bool netplay_resources_verified(const ModResolution& plan, } bool mod_runtime_prepare_resources(const std::filesystem::path& disc_path, std::string* error) { + HostLaunchTimingScope timing(HOST_LAUNCH_PREPARE_RESOURCES); RuntimeMods& s = state(); - if (!s.initialized) return true; + if (!s.initialized) { timing.success(); return true; } std::filesystem::path media_cache; #if defined(_WIN32) if (const char* local = std::getenv("LOCALAPPDATA")) media_cache = local; @@ -1584,23 +1606,31 @@ bool mod_runtime_prepare_resources(const std::filesystem::path& disc_path, std:: if (error) *error = s.error; return false; } + timing.success(); return true; } bool mod_runtime_verify_session_plan_fp(std::string* error); bool mod_runtime_commit(const std::filesystem::path& disc_path, std::string* error, bool save_selection) { + HostLaunchTimingScope timing(HOST_LAUNCH_COMMIT); RuntimeMods& s = state(); - if (!s.initialized) return true; + if (!s.initialized) { timing.success(); return true; } if (disc_path != s.disc_path) { + HostLaunchTimingScope hash_timing(HOST_LAUNCH_DISC_HASH); std::string hash_error, digest; if (!sha256_file(disc_path, digest, &hash_error)) digest.clear(); + else hash_timing.success(); s.disc_path = disc_path; s.disc_sha256 = std::move(digest); } if (!mod_runtime_prepare_resources(disc_path, error)) return false; - ModResolution plan = - s.manager.resolve(s.game_id, s.exe_sha256, s.disc_sha256); + ModResolution plan; + { + HostLaunchTimingScope resolve_timing(HOST_LAUNCH_RESOLVE); + plan = s.manager.resolve(s.game_id, s.exe_sha256, s.disc_sha256); + if (plan.ok) resolve_timing.success(); + } s.validation = plan; /* A derived activation is not in state.toml, so name it: a player (or a * test) reading the log can see why a hidden feature is running. */ @@ -1625,28 +1655,40 @@ bool mod_runtime_commit(const std::filesystem::path& disc_path, std::string* err if (error) *error = s.error; return false; } - for (const ModResolution::Overlay& overlay : plan.overlays) { - if (overlay.expected_sha256.empty()) continue; - std::string actual; - if (!sha256_disc_range( - s.disc_path, overlay.target, overlay.location, - overlay.payload.size(), actual, &s.error) || - actual != overlay.expected_sha256) { - if (s.error.empty()) - s.error = overlay.package_id + "/" + overlay.feature_id + - ": stock overlay range checksum failed"; + { + HostLaunchTimingScope overlay_timing(HOST_LAUNCH_OVERLAY_VERIFY); + for (const ModResolution::Overlay& overlay : plan.overlays) { + if (overlay.expected_sha256.empty()) continue; + std::string actual; + if (!sha256_disc_range( + s.disc_path, overlay.target, overlay.location, + overlay.payload.size(), actual, &s.error) || + actual != overlay.expected_sha256) { + if (s.error.empty()) + s.error = overlay.package_id + "/" + overlay.feature_id + + ": stock overlay range checksum failed"; + if (error) *error = s.error; + return false; + } + } + overlay_timing.success(); + } + std::filesystem::path effective_disc; + { + HostLaunchTimingScope derived_timing(HOST_LAUNCH_DERIVED_DISC); + if (!materialize_derived_disc(s, plan, effective_disc, &s.error)) { if (error) *error = s.error; return false; } + derived_timing.success(); } - std::filesystem::path effective_disc; - if (!materialize_derived_disc(s, plan, effective_disc, &s.error)) { - if (error) *error = s.error; - return false; - } - if (save_selection && !s.manager.save_state(&s.error)) { - if (error) *error = s.error; - return false; + if (save_selection) { + HostLaunchTimingScope save_timing(HOST_LAUNCH_SAVE_STATE); + if (!s.manager.save_state(&s.error)) { + if (error) *error = s.error; + return false; + } + save_timing.success(); } /* Hooks follow activation, never a bare commit: a new plan runs none of * its function-entry hooks until mod_runtime_activate_plugins(). */ @@ -1655,10 +1697,15 @@ bool mod_runtime_commit(const std::filesystem::path& disc_path, std::string* err s.audio_tracks.clear(); s.extent_start = 0; s.plan = std::move(plan); - build_disc_index(s); + { + HostLaunchTimingScope index_timing(HOST_LAUNCH_BUILD_DISC_INDEX); + build_disc_index(s); + index_timing.success(); + } s.effective_disc_path = std::move(effective_disc); s.main_applied = false; s.error.clear(); + timing.success(); return true; } @@ -2163,22 +2210,27 @@ bool mod_runtime_read_disc_file_sectors(const std::string& path, uint32_t max_by extern "C" void mod_runtime_activate_plugins(void) { using namespace PSXRecompV4; + HostLaunchTimingScope timing(HOST_LAUNCH_PLUGIN_ACTIVATION); RuntimeMods& s = state(); psx_projection_reset_session(); gpu_ws_set_native_scene_predicate(nullptr); psx_ram_reset_size_request(); gpu_hd_textures_shutdown(); - if (!s.initialized || !s.plan.ok) return; + if (!s.initialized || !s.plan.ok) { timing.success(); return; } s.disc_extents.clear(); s.audio_tracks.clear(); s.extent_start = 0; s.activating = true; for (const ModResolution::Plugin& plugin : s.plan.plugins) { + HostLaunchTimingScope plugin_timing(HOST_LAUNCH_PLUGIN_CALLBACK, + plugin.package_id.c_str(), plugin.feature_id.c_str()); PluginCallbackScope scope(s, &plugin); mod_invoke_activation_plugin(plugin.id); + plugin_timing.success(); } s.activating = false; build_function_entry_hooks(s); + timing.success(); } extern "C" void mod_runtime_on_vblank(void) { diff --git a/runtime/tests/host_launch_timing_helper.cpp b/runtime/tests/host_launch_timing_helper.cpp new file mode 100644 index 00000000..dc4e5c26 --- /dev/null +++ b/runtime/tests/host_launch_timing_helper.cpp @@ -0,0 +1,9 @@ +#include "host_launch_timing.h" + +/* Separate translation unit: catches accidentally per-includer ring/parent + * state, which would hide media-provider work from the runtime TCP reader. */ +void host_launch_timing_fixture_nested() { + PSXRecompV4::HostLaunchTimingScope scope(HOST_LAUNCH_MEDIA_PROVIDER, + "fixture.package", "fixture.feature"); + scope.success(); +} diff --git a/runtime/tests/test_host_launch_timing.cpp b/runtime/tests/test_host_launch_timing.cpp new file mode 100644 index 00000000..9ea2eaa6 --- /dev/null +++ b/runtime/tests/test_host_launch_timing.cpp @@ -0,0 +1,96 @@ +#include "host_launch_timing.h" + +#include +#include +#include +#include +#include + +using namespace PSXRecompV4; +void host_launch_timing_fixture_nested(); +static int failures; +static void check(bool value, const char* message) { + if (!value) { std::cerr << "FAIL: " << message << '\n'; ++failures; } +} + +int main() { + static_assert(std::is_trivially_copyable::value, + "C-facing snapshot must remain POD"); + HostLaunchTimingEvent events[HOST_LAUNCH_TIMING_CAPACITY]{}; + uint64_t total = 0, overwritten = 0; + { + HostLaunchTimingScope parent(HOST_LAUNCH_COMMIT); + host_launch_timing_fixture_nested(); + parent.success(); + } + auto n = host_launch_timing_ring().snapshot(events, 256, &total, &overwritten); + check(n == 2 && total == 2 && overwritten == 0, "shared ring across translation units"); + check(events[0].parent_id == events[1].scope_id && events[1].parent_id == 0, + "shared nested parent across translation units"); + check(events[0].scope_id > events[1].scope_id && events[0].seq < events[1].seq, + "completion order differs from start order"); + check(events[0].start_us >= events[1].start_us && + events[0].start_us + events[0].duration_us <= + events[1].start_us + events[1].duration_us, "child time inside parent"); + check(events[0].ok && events[1].ok && + std::string(events[0].package_id) == "fixture.package", "success and metadata retained"); + + HostLaunchTimingRing ring; + try { + HostLaunchTimingScope failed(HOST_LAUNCH_PREPARE_RESOURCES, nullptr, nullptr, ring); + HostLaunchTimingScope child(HOST_LAUNCH_MEDIA_PROVIDER, nullptr, nullptr, ring); + throw std::runtime_error("fixture failure"); + } catch (const std::runtime_error&) { } + { + const std::string long_label(100, 'x'); + HostLaunchTimingScope next(HOST_LAUNCH_RESOLVE, long_label.c_str(), "short", ring); + next.success(); + } + n = ring.snapshot(events, 256, &total, &overwritten); + check(n == 3 && !events[0].ok && !events[1].ok && events[2].ok, + "exception exits remain failures and next call succeeds"); + check(events[0].parent_id == events[1].scope_id && events[2].parent_id == 0, + "exception restores enclosing context"); + check(events[2].labels_truncated && std::strlen(events[2].package_id) == 63 && + std::string(events[2].feature_id) == "short", "bounded labels report truncation"); + + for (unsigned i = 0; i < HOST_LAUNCH_TIMING_CAPACITY; ++i) { + HostLaunchTimingScope scope(HOST_LAUNCH_DISC_HASH, nullptr, nullptr, ring); + scope.success(); + } + n = ring.snapshot(events, 256, &total, &overwritten); + check(n == 256 && total == 259 && overwritten == 3, "wrap retains fixed capacity"); + for (uint32_t i = 1; i < n; ++i) + check(events[i].seq == events[i - 1].seq + 1, "wrapped snapshot oldest first"); + n = ring.snapshot(events, 2, &total, &overwritten); + check(n == 2 && events[0].seq == 258 && events[1].seq == 259, + "small reader receives newest entries without draining"); + check(ring.snapshot(nullptr, 256, &total, &overwritten) == 0 && total == 259, + "metadata query does not consume entries"); + + HostLaunchTimingRing concurrent; + auto writer = [&]() { + for (unsigned i = 0; i < 40; ++i) { + HostLaunchTimingScope parent(HOST_LAUNCH_COMMIT, nullptr, nullptr, concurrent); + HostLaunchTimingScope child(HOST_LAUNCH_RESOLVE, nullptr, nullptr, concurrent); + child.success(); parent.success(); + } + }; + std::thread a(writer), b(writer); + a.join(); b.join(); + n = concurrent.snapshot(events, 256, &total, &overwritten); + check(n == 160 && total == 160 && overwritten == 0, "concurrent completion count preserved"); + for (uint32_t i = 0; i < n; ++i) { + check(events[i].seq == i + 1 && events[i].ok, "concurrent sequence publication"); + if (events[i].stage == HOST_LAUNCH_COMMIT) + check(events[i].parent_id == 0, "thread-local roots do not inherit other writer"); + else { + bool found = false; + for (uint32_t j = i + 1; j < n; ++j) + if (events[j].scope_id == events[i].parent_id && + events[j].stage == HOST_LAUNCH_COMMIT) found = true; + check(found, "concurrent child belongs to a completed parent"); + } + } + return failures ? 1 : 0; +} diff --git a/runtime/tests/test_host_launch_timings_protocol.py b/runtime/tests/test_host_launch_timings_protocol.py new file mode 100644 index 00000000..96d9aafc --- /dev/null +++ b/runtime/tests/test_host_launch_timings_protocol.py @@ -0,0 +1,112 @@ +"""Execute the production TCP handler/helpers and real ring through the C ABI. + +No server, game, SDL, or persistent log. Missing compilers are an explicit skip. +""" +import json +import os +from pathlib import Path +import re +import shutil +import subprocess +import tempfile +import unittest + +from test_wtrace_dump import matching_brace + +ROOT = Path(__file__).resolve().parents[2] + + +def function(source, name): + match = re.search(r'^(?:static |extern "C" )[^;{}]+\b' + name + + r'\([^;{}]*\)\s*\{', source, re.M) + if not match: + raise AssertionError(f"production function missing: {name}") + return source[match.start():matching_brace(source, match.end() - 1) + 1] + + +class HostLaunchProtocol(unittest.TestCase): + @classmethod + def setUpClass(cls): + cc, cxx = os.environ.get("CC", "cc"), os.environ.get("CXX", "c++") + if not shutil.which(cc) or not shutil.which(cxx): + raise unittest.SkipTest("set CC and CXX to the native compilers") + cls.temp = tempfile.TemporaryDirectory() + cls.addClassCleanup(cls.temp.cleanup) + temp = Path(cls.temp.name) + debug = (ROOT / "runtime/src/debug_server.c").read_text(encoding="utf-8") + runtime = (ROOT / "runtime/src/mod_runtime.cpp").read_text(encoding="utf-8") + harness = '''#include +#include +#include +#include "host_launch_timing.h" +void seed_host_launch_timing_fixture(int count); +static void debug_server_send_line(const char *line) { puts(line); } +static void send_err(int id, const char *error) { (void)id; (void)error; abort(); } +''' + for name in ("json_get_int", "json_escape_string", "handle_host_launch_timings"): + harness += function(debug, name) + "\n" + harness += '''int main(int argc, char **argv) { + if (argc != 3) return 2; + seed_host_launch_timing_fixture(atoi(argv[2])); + handle_host_launch_timings(42, argv[1]); + return 0; +} +''' + bridge = '#include "host_launch_timing.h"\n' + for name in ("host_launch_timing_snapshot", "host_launch_timing_stage_name"): + bridge += function(runtime, name) + "\n" + bridge += '''extern "C" void seed_host_launch_timing_fixture(int count) { + char label[64]; + for (unsigned i = 0; i < 63; ++i) label[i] = i % 3 == 0 ? '"' : i % 3 == 1 ? '\\\\' : '\\1'; + label[63] = 0; + for (int i = 0; i < count; ++i) { + PSXRecompV4::HostLaunchTimingScope scope(HOST_LAUNCH_MEDIA_PROVIDER, label, label); + if (i % 2 == 0) scope.success(); + } +} +''' + (temp / "handler.c").write_text(harness, encoding="utf-8") + (temp / "bridge.cpp").write_text(bridge, encoding="utf-8") + include = str(ROOT / "runtime/include") + cls.exe = temp / ("protocol.exe" if os.name == "nt" else "protocol") + for args in ([cc, "-std=c99", "-Wall", "-Wextra", "-Werror", "-I", include, + "-c", str(temp / "handler.c"), "-o", str(temp / "handler.o")], + [cxx, "-std=c++17", "-Wall", "-Wextra", "-Werror", "-pthread", + "-I", include, str(temp / "bridge.cpp"), str(temp / "handler.o"), + "-o", str(cls.exe)]): + subprocess.run(args, check=True, capture_output=True, text=True) + + def query(self, count=None, seeded=300): + request = {"cmd": "host_launch_timings"} + if count is not None: + request["count"] = count + output = subprocess.check_output([str(self.exe), json.dumps(request), str(seeded)], text=True) + return json.loads(output) + + def test_wrapped_maximum_labels_and_default_count(self): + result = self.query() + self.assertEqual((result["capacity"], result["total"], result["overwritten"]), (256, 300, 44)) + self.assertTrue(result["nested_durations_overlap"]) + self.assertEqual([e["seq"] for e in result["entries"]], list(range(45, 301))) + for e in result["entries"]: + self.assertEqual(e["stage"], "media_provider") + self.assertEqual(e["package"], '"\\\x01' * 21) + self.assertEqual(e["feature"], e["package"]) + self.assertEqual(e["labels_truncated"], 0) + self.assertEqual(e["ok"], int(e["seq"] % 2 == 1)) + + def test_count_clamping(self): + for count, expected in ((0, 1), (-10, 1), (1, 1), (3, 3), (256, 256), (1000, 256)): + result = self.query(count) + self.assertEqual(len(result["entries"]), expected) + self.assertEqual(result["entries"][-1]["seq"], 300) + + def test_empty_ring(self): + result = self.query(seeded=0) + self.assertEqual((result["total"], result["overwritten"], result["entries"]), (0, 0, [])) + + +if __name__ == "__main__": + suite = unittest.defaultTestLoader.loadTestsFromTestCase(HostLaunchProtocol) + result = unittest.TextTestRunner().run(suite) + raise SystemExit(77 if result.skipped else 0 if result.wasSuccessful() else 1) diff --git a/runtime/tests/test_mod_runtime.cpp b/runtime/tests/test_mod_runtime.cpp index 02b069b6..076f9e7d 100644 --- a/runtime/tests/test_mod_runtime.cpp +++ b/runtime/tests/test_mod_runtime.cpp @@ -1,4 +1,5 @@ #include "mod_runtime.h" +#include "host_launch_timing.h" #include "mod_packages.h" #include "mod_plugins.h" #include "psx_sha256.h" @@ -319,6 +320,47 @@ static std::string sha256_hex(const std::vector& bytes) { return out; } +static uint64_t launch_timing_total() { + uint64_t total = 0; + host_launch_timing_snapshot(nullptr, 0, &total, nullptr); + return total; +} + +static void check_commit_timing(uint64_t before, bool ok, bool hashed) { + HostLaunchTimingEvent events[HOST_LAUNCH_TIMING_CAPACITY]{}; + const auto n = host_launch_timing_snapshot(events, HOST_LAUNCH_TIMING_CAPACITY, + nullptr, nullptr); + const HostLaunchTimingEvent* commit = nullptr; + for (uint32_t i = 0; i < n; ++i) + if (events[i].seq > before && events[i].stage == HOST_LAUNCH_COMMIT) + commit = &events[i]; + check(commit && commit->ok == unsigned(ok), "real commit outcome retained by C snapshot"); + if (!commit) return; + uint32_t stages = 0; + for (uint32_t i = 0; i < n; ++i) { + const auto& e = events[i]; + if (e.seq <= before || e.parent_id != commit->scope_id) continue; + stages |= 1u << e.stage; + check(e.start_us >= commit->start_us && + e.start_us + e.duration_us <= commit->start_us + commit->duration_us, + "real commit child measurement nested inside total"); + } + check(bool(stages & (1u << HOST_LAUNCH_DISC_HASH)) == hashed, + "disc hash timing follows actual digest reuse"); + const uint32_t required = (1u << HOST_LAUNCH_PREPARE_RESOURCES) | + (1u << HOST_LAUNCH_RESOLVE); + check((stages & required) == required, "real preparation and resolution observed"); + if (ok) { + const uint32_t final = (1u << HOST_LAUNCH_OVERLAY_VERIFY) | + (1u << HOST_LAUNCH_DERIVED_DISC) | (1u << HOST_LAUNCH_SAVE_STATE) | + (1u << HOST_LAUNCH_BUILD_DISC_INDEX); + check((stages & final) == final, "real successful commit final stages observed"); + } else { + check(!(stages & (1u << HOST_LAUNCH_BUILD_DISC_INDEX)), + "rejected commit does not invent final-stage completion"); + } +} + int main() { const fs::path root = fs::temp_directory_path() / "psxrecomp-mod-runtime-test"; std::error_code ec; @@ -556,8 +598,10 @@ int main() { check(PSXRecompV4::mod_runtime_initialize( root, "SLUS-RUNTIME", 0x80002000, {}, &error), error.c_str()); + const auto first_commit_timing = launch_timing_total(); check(PSXRecompV4::mod_runtime_commit(cue_path, &error), "CUE and its data-track BIN must have the same mod target identity"); + check_commit_timing(first_commit_timing, true, true); /* Committed but not yet activated: no hook may run. */ psx_mod_instruction(&entry_cpu, 0x80003004u, 0x90A30014u); check(instruction_hits == 0 && !g_psx_mod_instruction_hooks, "instruction hooks await activation"); @@ -1193,7 +1237,9 @@ int main() { check(PSXRecompV4::mod_runtime_initialize(loose_root, "READER", 0, {}, &error), "loose resource initialize"); check(PSXRecompV4::mod_runtime_commit(iso_path, &error), "unverified file remains usable offline"); check(PSXRecompV4::mod_runtime_plan_fingerprint_portable().empty(), "unverified resource has no online fingerprint"); + const auto rejected_commit_timing = launch_timing_total(); check(!PSXRecompV4::mod_runtime_commit(iso_path, &error, false), "online commit rejects unverified resource"); + check_commit_timing(rejected_commit_timing, false, false); check(!PSXRecompV4::mod_runtime_commit_for_direct_netplay(iso_path, &error), "LAN also refuses unverified resources"); test_match_caps = {}; test_match_caps.valid = 1;