Sfoglia il codice sorgente

add debug-level boot timing

Times the two Sunrise entry points and reports the duration on the debug
channel only, so a normal run at warn or info is unchanged.

- core::initialize: begin marker plus a complete line carrying ms, on both
  the success and failure paths. The marker cannot be emitted before
  log::initialize because that stage is what brings the sinks up, so it sits
  immediately after it while the duration still counts from function entry.
- activate_main_once: begin and complete markers around the image sweep and
  game hook installation, which is what dominates that call.

Both use GetTickCount64 and the ms= field, matching the existing idiom in
hash_name_build.cpp and spawn_set_build.cpp. The markers use phase= rather
than stage= because those lines already carry stage=main.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Joe McNally 3 settimane fa
parent
commit
b6ad2d99fe

+ 35 - 0
Sunrise/src/client/runtime/client_hook_activation.cpp

@@ -1,6 +1,7 @@
 #include <Windows.h>
 
 #include <array>
+#include <cstdint>
 #include <cstdio>
 #include <span>
 #include <string_view>
@@ -101,6 +102,31 @@ void report_resolve_failure() noexcept {
         core::log::Channel::client, core::log::Level::error, std::string_view(line.data(), length));
 }
 
+/**
+ * Reports how long main activation took, for the debug channel only.
+ * Timing is diagnostic, so it never appears at the levels a normal run uses.
+ * @param event Event and phase text the duration is appended to.
+ * @param startedTick Tick count taken when activation began.
+ * @param result Outcome text for the log line.
+ */
+void report_elapsed(const char* event, std::uint64_t startedTick, const char* result) noexcept {
+    const std::uint64_t elapsed = GetTickCount64() - startedTick;
+    std::array<char, 96> line{};
+    const int written = std::snprintf(line.data(),
+                                      line.size(),
+                                      "%s ms=%llu result=%s",
+                                      event,
+                                      static_cast<unsigned long long>(elapsed),
+                                      result);
+    if (written <= 0) {
+        return;
+    }
+    const auto length = static_cast<std::size_t>(written) < line.size()
+                            ? static_cast<std::size_t>(written)
+                            : line.size() - 1;
+    core::log::write(core::log::Channel::client, core::log::Level::debug, {line.data(), length});
+}
+
 /** Clears both main-image target groups while no game hook owns their entries. */
 void clear_game_targets() noexcept {
     targets::game::content::clear();
@@ -183,10 +209,19 @@ bool activate_main_once() noexcept {
         ReleaseSRWLockExclusive(&runtime::g_lock);
         return active;
     }
+    // The image sweep dominates this call, so the pair of debug markers around it is what a
+    // boot-time measurement reads. Both are diagnostic and stay off at the usual levels.
+    core::log::write(
+        core::log::Channel::client, core::log::Level::debug, "ev=activate stage=main phase=begin");
     // The sweep stalls whichever thread calls it, so the overlay says what is happening. It
     // only reaches the screen once the presentation hooks are installed.
     core::ui::busy::begin(core::ui::busy::Task::initialization);
+    // Started after the overlay is up, because begin blocks for up to half a second waiting on
+    // presents. That wait belongs to the overlay, not to the work being measured.
+    const std::uint64_t startedTick = GetTickCount64();
     const bool active = runtime::activate_required_main_locked();
+    runtime::report_elapsed(
+        "ev=activate stage=main phase=complete", startedTick, active ? "ok" : "fail");
     core::ui::busy::end(core::ui::busy::Task::initialization);
     if (!active) {
         // A failed sweep latches too: repeating it stalls the frame loop for nothing.

+ 56 - 18
Sunrise/src/core/runtime/core_runtime.cpp

@@ -4,6 +4,7 @@
 
 #include <array>
 #include <atomic>
+#include <cstdint>
 #include <cstdio>
 #include <string_view>
 
@@ -77,6 +78,31 @@ void report_stage_failure(const char* stage) noexcept {
     log::write(log::Channel::core, log::Level::error, event);
 }
 
+/**
+ * Reports how long one boot boundary took, for the debug channel only.
+ * Timing is diagnostic, so it never appears at the levels a normal run uses.
+ * @param event Event and phase text the duration is appended to.
+ * @param startedTick Tick count taken when the boundary began.
+ * @param result Outcome text for the log line.
+ */
+void report_elapsed(const char* event, std::uint64_t startedTick, const char* result) noexcept {
+    const std::uint64_t elapsed = GetTickCount64() - startedTick;
+    std::array<char, 96> line{};
+    const int written = std::snprintf(line.data(),
+                                      line.size(),
+                                      "%s ms=%llu result=%s",
+                                      event,
+                                      static_cast<unsigned long long>(elapsed),
+                                      result);
+    if (written <= 0) {
+        return;
+    }
+    const auto length = static_cast<std::size_t>(written) < line.size()
+                            ? static_cast<std::size_t>(written)
+                            : line.size() - 1;
+    log::write(log::Channel::core, log::Level::debug, {line.data(), length});
+}
+
 } // namespace
 
 /** Initializes every runtime layer in dependency order. */
@@ -86,6 +112,8 @@ bool initialize(void* module) noexcept {
         ReleaseSRWLockExclusive(&g_runtimeLock);
         return true;
     }
+    // Taken before the first stage, so the reported duration covers settings and the sinks too.
+    const std::uint64_t startedTick = GetTickCount64();
 
     if (!settings::initialize(module)) {
         // Settings name their own failure; the sinks do not exist yet to carry a second line.
@@ -97,27 +125,36 @@ bool initialize(void* module) noexcept {
     const char* stage = nullptr;
     if (!log::initialize(module, settings::get().logging)) {
         stage = "logging";
-    } else if (!ui::runtime::initialize(settings::get().client.userInterface)) {
-        stage = "ui";
-    } else if (!ui::modules::logs::initialize()) {
-        stage = "ui_logs";
-    } else if (!state::entitlements::publish(settings::get().server.entitlements)) {
-        stage = "entitlements";
-    } else if (!state::initialize(module,
-                                  settings::get().initialAccount,
-                                  settings::get().initialActivityDefaults)) {
-        stage = "state";
-    } else if (!initialize_content_manifest(module)) {
-        stage = "content_manifest";
-    } else if (!middleware::initialize()) {
-        stage = "middleware";
-    } else if (!server::initialize()) {
-        stage = "server";
-    } else if (!client::initialize(module)) {
-        stage = "client";
+    } else {
+        // The sinks exist only from here, so this is the earliest a begin marker can reach a
+        // channel. The duration it pairs with still counts from function entry.
+        log::write(log::Channel::core, log::Level::debug, "ev=initialize phase=begin");
+        if (!ui::runtime::initialize(settings::get().client.userInterface)) {
+            stage = "ui";
+        } else if (!ui::modules::logs::initialize()) {
+            stage = "ui_logs";
+        } else if (!state::entitlements::publish(settings::get().server.entitlements)) {
+            stage = "entitlements";
+        } else if (!state::initialize(module,
+                                      settings::get().initialAccount,
+                                      settings::get().initialActivityDefaults)) {
+            stage = "state";
+        } else if (!initialize_content_manifest(module)) {
+            stage = "content_manifest";
+        } else if (!middleware::initialize()) {
+            stage = "middleware";
+        } else if (!server::initialize()) {
+            stage = "server";
+        } else if (!client::initialize(module)) {
+            stage = "client";
+        }
     }
     if (stage != nullptr) {
         report_stage_failure(stage);
+        // Reported before the unwind, so this measures initialization alone and stays comparable
+        // with the success line. The unwind's own quiesce waits would otherwise be counted here.
+        // A logging-stage failure has no sinks left to carry it, and reports nothing.
+        report_elapsed("ev=initialize phase=complete", startedTick, "fail");
         // Reverse every stage because the failing expression may have completed earlier stages.
         (void)client::shutdown();
         server::shutdown();
@@ -136,6 +173,7 @@ bool initialize(void* module) noexcept {
     }
     g_initialized.store(true, std::memory_order_release);
     log::write(log::Channel::core, log::Level::info, "ev=initialize result=ok");
+    report_elapsed("ev=initialize phase=complete", startedTick, "ok");
     ReleaseSRWLockExclusive(&g_runtimeLock);
     return true;
 }