Merge reviewed host launch timing scopes (PR551)

# Conflicts:
#	runtime/src/mod_runtime.cpp

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.
+
 <!-- BEGIN AUTOGENERATED COMMAND INDEX -- edit tools/gen_tcp_commands.py, not this block -->
 
 ## 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":"<name>"}` 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":"<name>"}` 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` | ✓ | ✓ | ✓ |

runtime/CMakeLists.txt

@@ -23,6 +23,12 @@ psxrecomp_add_runtime_target(psx-runtime
 # (docs/ENHANCEMENTS.md G1.10). Titles get their <exe>_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")

runtime/include/host_launch_timing.h

@@ -0,0 +1,145 @@
+#pragma once
+
+#include <stdint.h>
+
+/* 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 <algorithm>
+#include <array>
+#include <chrono>
+#include <cstring>
+#include <mutex>
+
+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<HostLaunchTimingEvent, HOST_LAUNCH_TIMING_CAPACITY> events_{};
+    uint64_t started_ = 0, completed_ = 0;
+public:
+    uint64_t begin() {
+        std::lock_guard<std::mutex> lock(mutex_);
+        return ++started_;
+    }
+    void finish(HostLaunchTimingEvent event) {
+        std::lock_guard<std::mutex> 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<std::mutex> 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<uint32_t>(std::min<uint64_t>(
+            std::min<uint64_t>(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<uint64_t>(std::chrono::duration_cast<std::chrono::microseconds>(
+        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_t>(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

runtime/src/debug_server.c

@@ -17,6 +17,7 @@
 #endif
 #include <time.h>
 #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 },

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

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<std::string, fs::path> 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())

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) {

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();
+}

runtime/tests/test_host_launch_timing.cpp

@@ -0,0 +1,96 @@
+#include "host_launch_timing.h"
+
+#include <iostream>
+#include <stdexcept>
+#include <string>
+#include <thread>
+#include <type_traits>
+
+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<HostLaunchTimingEvent>::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;
+}

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 <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#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)

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<uint8_t>& 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;