From 8ba237ccf55f18a7649d88a6afd8795ac0cc78df Mon Sep 17 00:00:00 2001 From: Matthew Stanley <1379tech@gmail.com> Date: Tue, 6 Oct 2026 22:46:05 -0700 Subject: [PATCH] Retain host launch and mod commit stage timings for TCP diagnostics --- docs/TCP_COMMANDS.md | 29 ++++ runtime/CMakeLists.txt | 6 + runtime/include/host_launch_timing.h | 145 ++++++++++++++++++++ runtime/src/debug_server.c | 49 +++++++ runtime/src/main.cpp | 9 ++ runtime/src/mod_packages.cpp | 10 +- runtime/src/mod_runtime.cpp | 100 ++++++++++---- runtime/tests/host_launch_timing_helper.cpp | 9 ++ runtime/tests/test_host_launch_timing.cpp | 96 +++++++++++++ runtime/tests/test_mod_runtime.cpp | 46 +++++++ 10 files changed, 473 insertions(+), 26 deletions(-) create mode 100644 runtime/include/host_launch_timing.h create mode 100644 runtime/tests/host_launch_timing_helper.cpp create mode 100644 runtime/tests/test_host_launch_timing.cpp diff --git a/docs/TCP_COMMANDS.md b/docs/TCP_COMMANDS.md index 30216a88..5fcf00a5 100644 --- a/docs/TCP_COMMANDS.md +++ b/docs/TCP_COMMANDS.md @@ -432,6 +432,35 @@ The TCP server is the canonical instrumentation surface. Rule 3 in `CLAUDE.md` i +## `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`). diff --git a/runtime/CMakeLists.txt b/runtime/CMakeLists.txt index eacbe427..830c43b3 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) 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 6f64b711..0c575199 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" @@ -8125,6 +8126,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, @@ -15172,6 +15220,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 77907729..d8b0c502 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" @@ -15437,6 +15438,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 = @@ -15622,6 +15624,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) { @@ -16588,6 +16591,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 { @@ -16598,6 +16602,7 @@ int main(int argc, char** argv) { return 1; } } + timing.success(); } if (game_config_path || disc_override_path || !resolved_disc.empty()) { @@ -16613,6 +16618,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)) { @@ -16628,6 +16634,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 @@ -18749,6 +18756,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)) { @@ -18768,6 +18776,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 bfc5af09..6a80a3e0 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 3e4fa78d..3c2a09fc 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" @@ -12,6 +13,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 @@ -1164,6 +1181,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)) { @@ -1171,10 +1189,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() @@ -1185,6 +1205,7 @@ int provider_commit_netplay(void*, const char* image_path) { return 0; } state().error.clear(); + timing.success(); return 1; } @@ -1531,8 +1552,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; @@ -1546,23 +1568,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. */ @@ -1587,28 +1617,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(). */ @@ -1617,10 +1659,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; } @@ -2125,21 +2172,26 @@ 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(); - 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_mod_runtime.cpp b/runtime/tests/test_mod_runtime.cpp index a3f941a6..3bb91527 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" @@ -288,6 +289,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; @@ -525,8 +567,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"); @@ -1162,7 +1206,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;