Merge pull request #24 from SkyzerFlyzer/perf/anchored-pattern-scan

 Anchor signature scans on their first exact byte (~4s faster boot)

Sunrise/src/client/patterns/registry.cpp

@@ -1,23 +1,43 @@
 #include "registry.h"
 
+#include <cstring>
+
 namespace sunrise::client::patterns {
 namespace {
 
+/** Returned by next_candidate when a range holds no further anchor byte. */
+constexpr std::size_t kNoCandidate = static_cast<std::size_t>(-1);
+
+/**
+ * The one exact byte a pattern's candidate search keys on.
+ * Only exact bytes can be searched for, so a pattern without one cannot be scanned at all. That
+ * is the same condition the sweep already rejected patterns on, so the anchor doubles as the
+ * validity check.
+ */
+struct Anchor {
+    /** Position of the anchor byte inside the pattern. */
+    std::size_t index{};
+    /** The byte itself, held unsigned so it reaches memchr without sign extension. */
+    unsigned char value{};
+    /** False for a pattern the sweep cannot scan, which is the pattern it must reject. */
+    bool valid{};
+};
+
 /**
- * Validates one pattern before the shared image sweep.
+ * Picks the anchor byte for one pattern.
  * @param pattern Pattern name, bytes, and exact-byte mask.
- * @return True when the pattern has a name, bytes, and at least one exact byte.
+ * @return A valid anchor when the pattern has a name, bytes, and at least one exact byte.
  */
-[[nodiscard]] bool is_valid(const Pattern& pattern) noexcept {
+[[nodiscard]] Anchor anchor_of(const Pattern& pattern) noexcept {
     if (pattern.name.empty() || pattern.bytes.empty()) {
-        return false;
+        return {};
     }
-    for (const PatternByte byte : pattern.bytes) {
-        if (byte.exact) {
-            return true;
+    for (std::size_t index = 0; index < pattern.bytes.size(); ++index) {
+        if (pattern.bytes[index].exact) {
+            return Anchor{index, std::to_integer<unsigned char>(pattern.bytes[index].value), true};
         }
     }
-    return false;
+    return {};
 }
 
 /**
@@ -29,7 +49,9 @@ namespace {
 [[nodiscard]] bool matches_at(std::span<const std::byte> image,
                               std::size_t offset,
                               std::span<const PatternByte> pattern) noexcept {
-    if (pattern.size() > image.size() - offset) {
+    // The offset is checked before the subtraction, so this holds for any caller value rather
+    // than only for the bounded offsets next_candidate produces.
+    if (offset >= image.size() || pattern.size() > image.size() - offset) {
         return false;
     }
     for (std::size_t index = 0; index < pattern.size(); ++index) {
@@ -40,9 +62,41 @@ namespace {
     return true;
 }
 
+/**
+ * Finds the next offset at or after one start where the anchor byte lines up.
+ * The bytes in between cannot begin a match, so memchr skips them at memory speed instead of the
+ * sweep testing every one of them.
+ * @param range One executable range.
+ * @param patternSize Pattern length, which bounds the last offset that can hold a whole match.
+ * @param anchor Valid anchor for that pattern.
+ * @param from First offset to consider.
+ * @return Candidate offset, or kNoCandidate when the range holds no further one.
+ */
+[[nodiscard]] std::size_t next_candidate(std::span<const std::byte> range,
+                                         std::size_t patternSize,
+                                         const Anchor& anchor,
+                                         std::size_t from) noexcept {
+    if (patternSize > range.size()) {
+        return kNoCandidate;
+    }
+    const std::size_t lastOffset = range.size() - patternSize;
+    if (from > lastOffset) {
+        return kNoCandidate;
+    }
+    // The anchor sits at offset + index, so the search window is the offset window shifted by it.
+    const std::size_t first = from + anchor.index;
+    const std::size_t last = lastOffset + anchor.index;
+    const void* const hit = std::memchr(range.data() + first, anchor.value, last - first + 1);
+    if (hit == nullptr) {
+        return kNoCandidate;
+    }
+    const auto* const found = static_cast<const std::byte*>(hit);
+    return static_cast<std::size_t>(found - range.data()) - anchor.index;
+}
+
 } // namespace
 
-/** Resolves all patterns during one sweep over one executable range. */
+/** Resolves every registered pattern against one executable range. */
 bool resolve_all(std::span<std::byte> image,
                  std::span<const Pattern> patterns,
                  std::span<Match> matches) noexcept {
@@ -50,7 +104,7 @@ bool resolve_all(std::span<std::byte> image,
     return resolve_all(std::span(&range, 1), patterns, matches);
 }
 
-/** Resolves all patterns during one sweep over disjoint executable ranges. */
+/** Resolves every pattern across disjoint executable image ranges. */
 bool resolve_all(std::span<const ImageRange> image,
                  std::span<const Pattern> patterns,
                  std::span<Match> matches) noexcept {
@@ -59,27 +113,32 @@ bool resolve_all(std::span<const ImageRange> image,
     }
 
     for (std::size_t index = 0; index < patterns.size(); ++index) {
-        matches[index] = is_valid(patterns[index]) ? Match{MatchStatus::missing, nullptr} : Match{};
-    }
+        const Anchor anchor = anchor_of(patterns[index]);
+        matches[index] = anchor.valid ? Match{MatchStatus::missing, nullptr} : Match{};
+        if (!anchor.valid) {
+            continue;
+        }
 
-    for (const ImageRange range : image) {
-        for (std::size_t offset = 0; offset < range.bytes.size(); ++offset) {
-            for (std::size_t index = 0; index < patterns.size(); ++index) {
-                Match& match = matches[index];
-                if (match.status == MatchStatus::invalid
-                    || match.status == MatchStatus::ambiguous) {
-                    continue;
-                }
-                if (!matches_at(range.bytes, offset, patterns[index].bytes)) {
-                    continue;
+        Match& match = matches[index];
+        const std::span<const PatternByte> bytes = patterns[index].bytes;
+        for (const ImageRange range : image) {
+            std::size_t offset = 0;
+            while (match.status != MatchStatus::ambiguous) {
+                offset = next_candidate(range.bytes, bytes.size(), anchor, offset);
+                if (offset == kNoCandidate) {
+                    break;
                 }
-
-                if (match.status == MatchStatus::missing) {
-                    match = Match{MatchStatus::unique, range.bytes.data() + offset};
-                } else {
+                if (matches_at(range.bytes, offset, bytes)) {
                     // A second match invalidates the address instead of choosing one.
-                    match = Match{MatchStatus::ambiguous, nullptr};
+                    match = match.status == MatchStatus::missing
+                                ? Match{MatchStatus::unique, range.bytes.data() + offset}
+                                : Match{MatchStatus::ambiguous, nullptr};
                 }
+                ++offset;
+            }
+            // Ambiguous is final, so the remaining ranges cannot change this pattern's result.
+            if (match.status == MatchStatus::ambiguous) {
+                break;
             }
         }
     }
@@ -90,12 +149,15 @@ bool resolve_all(std::span<const ImageRange> image,
 std::size_t collect_matches(std::span<const ImageRange> image,
                             const Pattern& pattern,
                             std::span<std::byte*> output) noexcept {
-    if (!is_valid(pattern) || output.empty()) {
+    const Anchor anchor = anchor_of(pattern);
+    if (!anchor.valid || output.empty()) {
         return 0;
     }
     std::size_t count = 0;
     for (const ImageRange range : image) {
-        for (std::size_t offset = 0; offset < range.bytes.size(); ++offset) {
+        for (std::size_t offset = next_candidate(range.bytes, pattern.bytes.size(), anchor, 0);
+             offset != kNoCandidate;
+             offset = next_candidate(range.bytes, pattern.bytes.size(), anchor, offset + 1)) {
             if (!matches_at(range.bytes, offset, pattern.bytes)) {
                 continue;
             }

Sunrise/src/client/patterns/registry.h

@@ -37,7 +37,7 @@ struct ImageRange {
     std::span<std::byte> bytes;
 };
 
-/** Resolves every registered pattern during one image sweep. */
+/** Resolves every registered pattern against one executable range. */
 [[nodiscard]] bool resolve_all(std::span<std::byte> image,
                                std::span<const Pattern> patterns,
                                std::span<Match> matches) noexcept;

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>
@@ -102,6 +103,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();
@@ -186,10 +212,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.

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;
 }