From ba6af8115be0e52d88cd1528ca583c4decc060e6 Mon Sep 17 00:00:00 2001 From: server Date: Wed, 15 Apr 2026 16:22:10 +0200 Subject: [PATCH] Add pack runtime profiling hooks --- src/PackLib/CMakeLists.txt | 2 +- src/PackLib/M2Pack.cpp | 58 ++ src/PackLib/M2Pack.h | 2 + src/PackLib/M2PackRuntimeKeyProvider.cpp | 3 + src/PackLib/Pack.cpp | 28 + src/PackLib/Pack.h | 2 + src/PackLib/PackManager.cpp | 75 ++- src/PackLib/PackProfile.cpp | 494 ++++++++++++++++++ src/PackLib/PackProfile.h | 29 + .../PythonNetworkStreamPhaseGame.cpp | 2 + .../PythonNetworkStreamPhaseLoading.cpp | 2 + .../PythonNetworkStreamPhaseLogin.cpp | 2 + 12 files changed, 696 insertions(+), 3 deletions(-) create mode 100644 src/PackLib/PackProfile.cpp create mode 100644 src/PackLib/PackProfile.h diff --git a/src/PackLib/CMakeLists.txt b/src/PackLib/CMakeLists.txt index 9b028e0..1f9ff6b 100644 --- a/src/PackLib/CMakeLists.txt +++ b/src/PackLib/CMakeLists.txt @@ -1,4 +1,4 @@ -file(GLOB_RECURSE FILE_SOURCES "*.h" "*.c" "*.cpp") +file(GLOB_RECURSE FILE_SOURCES CONFIGURE_DEPENDS "*.h" "*.c" "*.cpp") add_library(PackLib STATIC ${FILE_SOURCES}) diff --git a/src/PackLib/M2Pack.cpp b/src/PackLib/M2Pack.cpp index ccddefb..9a8f5e1 100644 --- a/src/PackLib/M2Pack.cpp +++ b/src/PackLib/M2Pack.cpp @@ -1,6 +1,8 @@ #include "M2Pack.h" +#include "PackProfile.h" #include "M2PackRuntimeKeyProvider.h" +#include #include #include @@ -40,6 +42,7 @@ bool ReadPod(const uint8_t* bytes, std::size_t size, std::size_t& offset, T& out bool CM2Pack::Load(const std::string& path) { + m_source_path = path; std::error_code ec; m_file.map(path, ec); @@ -100,6 +103,7 @@ bool CM2Pack::Load(const std::string& path) bool CM2Pack::ValidateManifest() { std::array manifest_hash {}; + const auto hashStart = std::chrono::steady_clock::now(); crypto_generichash( manifest_hash.data(), manifest_hash.size(), @@ -107,6 +111,13 @@ bool CM2Pack::ValidateManifest() m_manifest_bytes.size(), nullptr, 0); + RecordPackProfileStage( + "m2p", + "manifest_hash", + m_manifest_bytes.size(), + manifest_hash.size(), + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - hashStart).count())); if (memcmp(manifest_hash.data(), m_header.manifest_hash, manifest_hash.size()) != 0) { @@ -121,17 +132,33 @@ bool CM2Pack::ValidateManifest() return false; } + const auto verifyStart = std::chrono::steady_clock::now(); if (crypto_sign_verify_detached( m_header.manifest_signature, m_manifest_bytes.data(), m_manifest_bytes.size(), publicKey->data()) != 0) { + RecordPackProfileStage( + "m2p", + "manifest_signature", + m_manifest_bytes.size(), + M2PACK_SIGNATURE_SIZE, + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - verifyStart).count())); TraceError("CM2Pack::ValidateManifest: manifest signature mismatch"); return false; } + RecordPackProfileStage( + "m2p", + "manifest_signature", + m_manifest_bytes.size(), + M2PACK_SIGNATURE_SIZE, + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - verifyStart).count())); std::size_t offset = 0; + const auto parseStart = std::chrono::steady_clock::now(); TM2PackManifestHeader manifest_header {}; if (!ReadPod(m_manifest_bytes.data(), m_manifest_bytes.size(), offset, manifest_header)) { @@ -184,6 +211,13 @@ bool CM2Pack::ValidateManifest() m_index.push_back(std::move(entry)); } + RecordPackProfileStage( + "m2p", + "manifest_parse", + m_manifest_bytes.size(), + m_index.size(), + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - parseStart).count())); return true; } @@ -196,6 +230,7 @@ bool CM2Pack::DecryptEntryPayload(const TM2PackEntry& entry, std::vectorAcquire(entry.stored_size); } decrypted.resize(entry.stored_size); + const auto decryptStart = std::chrono::steady_clock::now(); unsigned long long written = 0; if (crypto_aead_xchacha20poly1305_ietf_decrypt( decrypted.data(), @@ -214,6 +249,13 @@ bool CM2Pack::DecryptEntryPayload(const TM2PackEntry& entry, std::vector(std::chrono::duration_cast( + std::chrono::steady_clock::now() - decryptStart).count())); decrypted.resize(static_cast(written)); return true; @@ -243,7 +285,15 @@ bool CM2Pack::GetFileWithPool(const TM2PackEntry& entry, std::vector& r { result.resize(entry.original_size); ZSTD_DCtx* dctx = GetThreadLocalZstdContext(); + const auto decompressStart = std::chrono::steady_clock::now(); size_t written = ZSTD_decompressDCtx(dctx, result.data(), result.size(), compressed.data(), compressed.size()); + RecordPackProfileStage( + "m2p", + "zstd_decompress", + compressed.size(), + ZSTD_isError(written) ? 0 : written, + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - decompressStart).count())); if (pPool) { pPool->Release(std::move(compressed)); @@ -271,6 +321,7 @@ bool CM2Pack::GetFileWithPool(const TM2PackEntry& entry, std::vector& r } std::array plain_hash {}; + const auto hashStart = std::chrono::steady_clock::now(); crypto_generichash( plain_hash.data(), plain_hash.size(), @@ -278,6 +329,13 @@ bool CM2Pack::GetFileWithPool(const TM2PackEntry& entry, std::vector& r result.size(), nullptr, 0); + RecordPackProfileStage( + "m2p", + "plaintext_hash", + result.size(), + plain_hash.size(), + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - hashStart).count())); if (memcmp(plain_hash.data(), entry.plaintext_hash.data(), plain_hash.size()) != 0) { diff --git a/src/PackLib/M2Pack.h b/src/PackLib/M2Pack.h index 853a1be..eb2ae8f 100644 --- a/src/PackLib/M2Pack.h +++ b/src/PackLib/M2Pack.h @@ -72,6 +72,7 @@ public: bool Load(const std::string& path); const std::vector& GetIndex() const { return m_index; } + const std::string& GetSourcePath() const { return m_source_path; } bool GetFile(const TM2PackEntry& entry, std::vector& result); bool GetFileWithPool(const TM2PackEntry& entry, std::vector& result, CBufferPool* pPool); @@ -82,6 +83,7 @@ private: private: TM2PackHeader m_header {}; + std::string m_source_path; std::vector m_manifest_bytes; std::vector m_index; mio::mmap_source m_file; diff --git a/src/PackLib/M2PackRuntimeKeyProvider.cpp b/src/PackLib/M2PackRuntimeKeyProvider.cpp index 20fcc1f..343505c 100644 --- a/src/PackLib/M2PackRuntimeKeyProvider.cpp +++ b/src/PackLib/M2PackRuntimeKeyProvider.cpp @@ -1,4 +1,5 @@ #include "M2PackRuntimeKeyProvider.h" +#include "PackProfile.h" #include #include @@ -238,6 +239,8 @@ void ApplyCommandLineOption(const std::string& key, const std::string& value) bool InitializeM2PackRuntimeKeyProvider(const char* commandLine) { + InitializePackProfile(commandLine); + if (g_state.initialized) return true; diff --git a/src/PackLib/Pack.cpp b/src/PackLib/Pack.cpp index 0d24c9c..f5fd703 100644 --- a/src/PackLib/Pack.cpp +++ b/src/PackLib/Pack.cpp @@ -1,5 +1,8 @@ #include "Pack.h" +#include "PackProfile.h" #include "EterLib/BufferPool.h" + +#include #include static thread_local ZSTD_DCtx* g_zstdDCtx = nullptr; @@ -20,6 +23,7 @@ void CPack::DecryptData(uint8_t* data, size_t len, const uint8_t* nonce) bool CPack::Load(const std::string& path) { + m_source_path = path; std::error_code ec; m_file.map(path, ec); @@ -68,7 +72,15 @@ bool CPack::GetFileWithPool(const TPackFileEntry& entry, TPackFile& result, CBuf switch (entry.encryption) { case 0: { + const auto decompressStart = std::chrono::steady_clock::now(); size_t decompressed_size = ZSTD_decompressDCtx(dctx, result.data(), result.size(), m_file.data() + offset, entry.compressed_size); + RecordPackProfileStage( + "pck", + "zstd_decompress", + entry.compressed_size, + ZSTD_isError(decompressed_size) ? 0 : decompressed_size, + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - decompressStart).count())); if (decompressed_size != entry.file_size) { return false; } @@ -83,9 +95,25 @@ bool CPack::GetFileWithPool(const TPackFileEntry& entry, TPackFile& result, CBuf memcpy(compressed_data.data(), m_file.data() + offset, entry.compressed_size); + const auto decryptStart = std::chrono::steady_clock::now(); DecryptData(compressed_data.data(), entry.compressed_size, entry.nonce); + RecordPackProfileStage( + "pck", + "xchacha20_decrypt", + entry.compressed_size, + entry.compressed_size, + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - decryptStart).count())); + const auto decompressStart = std::chrono::steady_clock::now(); size_t decompressed_size = ZSTD_decompressDCtx(dctx, result.data(), result.size(), compressed_data.data(), compressed_data.size()); + RecordPackProfileStage( + "pck", + "zstd_decompress", + compressed_data.size(), + ZSTD_isError(decompressed_size) ? 0 : decompressed_size, + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - decompressStart).count())); if (pPool) { pPool->Release(std::move(compressed_data)); diff --git a/src/PackLib/Pack.h b/src/PackLib/Pack.h index 66ccc7e..81d4476 100644 --- a/src/PackLib/Pack.h +++ b/src/PackLib/Pack.h @@ -14,6 +14,7 @@ public: bool Load(const std::string& path); const std::vector& GetIndex() const { return m_index; } + const std::string& GetSourcePath() const { return m_source_path; } bool GetFile(const TPackFileEntry& entry, TPackFile& result); bool GetFileWithPool(const TPackFileEntry& entry, TPackFile& result, CBufferPool* pPool); @@ -22,6 +23,7 @@ private: void DecryptData(uint8_t* data, size_t len, const uint8_t* nonce); TPackFileHeader m_header; + std::string m_source_path; std::vector m_index; mio::mmap_source m_file; }; diff --git a/src/PackLib/PackManager.cpp b/src/PackLib/PackManager.cpp index 61feea3..ed52b0d 100644 --- a/src/PackLib/PackManager.cpp +++ b/src/PackLib/PackManager.cpp @@ -1,5 +1,8 @@ #include "PackManager.h" +#include "PackProfile.h" #include "EterLib/BufferPool.h" + +#include #include #include #include @@ -27,8 +30,16 @@ bool CPackManager::AddPack(const std::string& path) if (packPath.extension() == ".m2p") { std::shared_ptr pack = std::make_shared(); + const auto loadStart = std::chrono::steady_clock::now(); if (!pack->Load(path)) { + RecordPackProfileMount( + "m2p", + path, + false, + 0, + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - loadStart).count())); return false; } @@ -38,14 +49,29 @@ bool CPackManager::AddPack(const std::string& path) { m_m2_entries[entry.path] = std::make_pair(pack, entry); } + RecordPackProfileMount( + "m2p", + path, + true, + index.size(), + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - loadStart).count())); return true; } std::shared_ptr pack = std::make_shared(); + const auto loadStart = std::chrono::steady_clock::now(); if (!pack->Load(path)) { + RecordPackProfileMount( + "pck", + path, + false, + 0, + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - loadStart).count())); return false; } @@ -55,6 +81,13 @@ bool CPackManager::AddPack(const std::string& path) { m_entries[entry.file_name] = std::make_pair(pack, entry); } + RecordPackProfileMount( + "pck", + path, + true, + index.size(), + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - loadStart).count())); return true; } @@ -73,16 +106,37 @@ bool CPackManager::GetFileWithPool(std::string_view path, TPackFile& result, CBu if (m_load_from_pack) { auto m2it = m_m2_entries.find(buf); if (m2it != m_m2_entries.end()) { - return m2it->second.first->GetFileWithPool(m2it->second.second, result, pPool); + const auto loadStart = std::chrono::steady_clock::now(); + const bool ok = m2it->second.first->GetFileWithPool(m2it->second.second, result, pPool); + RecordPackProfileLoad( + "m2p", + m2it->second.first->GetSourcePath(), + buf, + ok, + ok ? result.size() : 0, + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - loadStart).count())); + return ok; } auto it = m_entries.find(buf); if (it != m_entries.end()) { - return it->second.first->GetFileWithPool(it->second.second, result, pPool); + const auto loadStart = std::chrono::steady_clock::now(); + const bool ok = it->second.first->GetFileWithPool(it->second.second, result, pPool); + RecordPackProfileLoad( + "pck", + it->second.first->GetSourcePath(), + buf, + ok, + ok ? result.size() : 0, + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - loadStart).count())); + return ok; } } // Fallback to disk (for files not in packs, like bgm folder) + const auto loadStart = std::chrono::steady_clock::now(); std::ifstream ifs(buf, std::ios::binary); if (ifs.is_open()) { ifs.seekg(0, std::ios::end); @@ -97,10 +151,27 @@ bool CPackManager::GetFileWithPool(std::string_view path, TPackFile& result, CBu } if (ifs.read((char*)result.data(), size)) { + RecordPackProfileLoad( + "disk", + "", + buf, + true, + result.size(), + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - loadStart).count())); return true; } } + RecordPackProfileLoad( + "disk", + "", + buf, + false, + 0, + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - loadStart).count())); + return false; } diff --git a/src/PackLib/PackProfile.cpp b/src/PackLib/PackProfile.cpp new file mode 100644 index 0000000..cae8dab --- /dev/null +++ b/src/PackLib/PackProfile.cpp @@ -0,0 +1,494 @@ +#include "PackProfile.h" + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include + +#include "EterBase/Utils.h" + +namespace +{ + +using Clock = std::chrono::steady_clock; + +constexpr const char* kPackProfileEnv = "M2PACK_PROFILE"; +constexpr const char* kPackProfileOutput = "log/pack_profile.txt"; +constexpr std::size_t kTopListLimit = 12; + +struct LoadStats +{ + std::uint64_t count = 0; + std::uint64_t failures = 0; + std::uint64_t output_bytes = 0; + std::uint64_t elapsed_us = 0; +}; + +struct MountStats +{ + std::uint64_t count = 0; + std::uint64_t failures = 0; + std::uint64_t entry_count = 0; + std::uint64_t elapsed_us = 0; +}; + +struct StageStats +{ + std::uint64_t count = 0; + std::uint64_t input_bytes = 0; + std::uint64_t output_bytes = 0; + std::uint64_t elapsed_us = 0; +}; + +struct PhaseMarker +{ + std::string phase; + std::uint64_t elapsed_us = 0; +}; + +struct PackProfileState +{ + bool initialized = false; + bool enabled = false; + std::string current_phase = "startup"; + Clock::time_point start_time {}; + std::vector markers; + std::map load_by_format; + std::map load_by_phase_format; + std::map load_by_phase_pack; + std::map load_by_extension; + std::map mount_by_format; + std::map mount_by_pack; + std::map stage_by_key; + std::mutex mutex; + + ~PackProfileState() + { + if (enabled) + { + std::lock_guard lock(mutex); + WriteReportLocked("shutdown"); + } + } + + void WriteReportLocked(std::string_view reason) const + { + std::error_code ec; + std::filesystem::create_directories("log", ec); + + std::ofstream output(kPackProfileOutput, std::ios::binary | std::ios::trunc); + if (!output) + { + return; + } + + output << "PACK PROFILE REPORT\n"; + output << "reason=" << reason << "\n"; + output << "current_phase=" << current_phase << "\n"; + + const auto uptime_us = start_time == Clock::time_point {} + ? 0 + : static_cast(std::chrono::duration_cast( + Clock::now() - start_time).count()); + output << "uptime_ms=" << FormatMs(uptime_us) << "\n\n"; + + output << "[phase_markers]\n"; + for (const auto& marker : markers) + { + output << marker.phase << "\t" << FormatMs(marker.elapsed_us) << " ms\n"; + } + output << "\n"; + + WriteMountSection(output, "[mounts_by_format]", mount_by_format); + WriteMountSection(output, "[mounts_by_pack]", mount_by_pack, kTopListLimit); + WriteLoadSection(output, "[loads_by_format]", load_by_format); + WriteLoadSection(output, "[loads_by_phase_format]", load_by_phase_format); + WriteLoadSection(output, "[top_phase_pack_loads]", load_by_phase_pack, kTopListLimit); + WriteLoadSection(output, "[top_extension_loads]", load_by_extension, kTopListLimit); + WriteStageSection(output, "[loader_stages]", stage_by_key); + } + + static std::string FormatMs(std::uint64_t elapsed_us) + { + std::ostringstream out; + out.setf(std::ios::fixed, std::ios::floatfield); + out.precision(3); + out << (static_cast(elapsed_us) / 1000.0); + return out.str(); + } + + static std::string ToLowerAscii(std::string value) + { + std::transform(value.begin(), value.end(), value.begin(), [](unsigned char ch) { + return static_cast(std::tolower(ch)); + }); + return value; + } + + static std::string ParsePackLabel(std::string_view pack_path) + { + const std::filesystem::path path { std::string(pack_path) }; + const auto filename = path.filename().string(); + if (!filename.empty()) + { + return ToLowerAscii(filename); + } + + return ToLowerAscii(std::string(pack_path)); + } + + static std::string ParseExtension(std::string_view request_path) + { + const std::filesystem::path path { std::string(request_path) }; + auto extension = path.extension().string(); + if (extension.empty()) + { + return ""; + } + + return ToLowerAscii(std::move(extension)); + } + + static std::string MakePhaseKey(std::string_view phase, std::string_view suffix) + { + std::string key; + key.reserve(phase.size() + suffix.size() + 3); + key.append(phase); + key.append(" | "); + key.append(suffix); + return key; + } + + template + static std::vector> SortByTimeDesc(const MapType& values) + { + using StatsType = typename MapType::mapped_type; + std::vector> sorted; + sorted.reserve(values.size()); + for (const auto& [key, stats] : values) + { + sorted.emplace_back(key, stats); + } + std::sort(sorted.begin(), sorted.end(), [](const auto& left, const auto& right) { + if (left.second.elapsed_us != right.second.elapsed_us) + { + return left.second.elapsed_us > right.second.elapsed_us; + } + + return left.first < right.first; + }); + return sorted; + } + + static void WriteLoadSection(std::ofstream& output, std::string_view header, const std::map& values, std::size_t limit = 0) + { + output << header << "\n"; + const auto sorted = SortByTimeDesc(values); + const std::size_t count = limit == 0 ? sorted.size() : std::min(limit, sorted.size()); + for (std::size_t i = 0; i < count; ++i) + { + const auto& [key, stats] = sorted[i]; + output + << key + << "\tcount=" << stats.count + << "\tfail=" << stats.failures + << "\tbytes=" << stats.output_bytes + << "\ttime_ms=" << FormatMs(stats.elapsed_us) + << "\n"; + } + output << "\n"; + } + + static void WriteMountSection(std::ofstream& output, std::string_view header, const std::map& values, std::size_t limit = 0) + { + output << header << "\n"; + std::vector> sorted(values.begin(), values.end()); + std::sort(sorted.begin(), sorted.end(), [](const auto& left, const auto& right) { + if (left.second.elapsed_us != right.second.elapsed_us) + { + return left.second.elapsed_us > right.second.elapsed_us; + } + + return left.first < right.first; + }); + + const std::size_t count = limit == 0 ? sorted.size() : std::min(limit, sorted.size()); + for (std::size_t i = 0; i < count; ++i) + { + const auto& [key, stats] = sorted[i]; + output + << key + << "\tcount=" << stats.count + << "\tfail=" << stats.failures + << "\tentries=" << stats.entry_count + << "\ttime_ms=" << FormatMs(stats.elapsed_us) + << "\n"; + } + output << "\n"; + } + + static void WriteStageSection(std::ofstream& output, std::string_view header, const std::map& values) + { + output << header << "\n"; + std::vector> sorted(values.begin(), values.end()); + std::sort(sorted.begin(), sorted.end(), [](const auto& left, const auto& right) { + if (left.second.elapsed_us != right.second.elapsed_us) + { + return left.second.elapsed_us > right.second.elapsed_us; + } + + return left.first < right.first; + }); + + for (const auto& [key, stats] : sorted) + { + output + << key + << "\tcount=" << stats.count + << "\tin=" << stats.input_bytes + << "\tout=" << stats.output_bytes + << "\ttime_ms=" << FormatMs(stats.elapsed_us) + << "\n"; + } + output << "\n"; + } +}; + +PackProfileState g_pack_profile; + +bool ParseBoolFlag(std::string value, bool& out) +{ + value.erase(std::remove_if(value.begin(), value.end(), [](unsigned char ch) { + return std::isspace(ch) != 0; + }), value.end()); + + std::transform(value.begin(), value.end(), value.begin(), [](unsigned char ch) { + return static_cast(std::tolower(ch)); + }); + + if (value == "1" || value == "true" || value == "yes" || value == "on") + { + out = true; + return true; + } + + if (value == "0" || value == "false" || value == "no" || value == "off") + { + out = false; + return true; + } + + return false; +} + +std::string GetEnvString(const char* name) +{ + char buffer[256]; + const DWORD len = GetEnvironmentVariableA(name, buffer, sizeof(buffer)); + if (len == 0 || len >= sizeof(buffer)) + { + return {}; + } + + return std::string(buffer, buffer + len); +} + +std::uint64_t CurrentElapsedUs() +{ + if (!g_pack_profile.enabled) + { + return 0; + } + + return static_cast(std::chrono::duration_cast( + Clock::now() - g_pack_profile.start_time).count()); +} + +} // namespace + +void InitializePackProfile(const char* commandLine) +{ + if (g_pack_profile.initialized) + { + return; + } + + g_pack_profile.initialized = true; + g_pack_profile.enabled = false; + + const std::string envProfile = GetEnvString(kPackProfileEnv); + if (!envProfile.empty()) + { + bool enabled = false; + if (ParseBoolFlag(envProfile, enabled)) + { + g_pack_profile.enabled = enabled; + } + } + + int argc = 0; + PCHAR* argv = CommandLineToArgv(const_cast(commandLine ? commandLine : ""), &argc); + if (argv) + { + for (int i = 0; i < argc; ++i) + { + const std::string arg = argv[i]; + if (arg != "--m2pack-profile") + { + continue; + } + + bool enabled = true; + if (i + 1 < argc) + { + const std::string next = argv[i + 1]; + if (!next.starts_with("--") && ParseBoolFlag(next, enabled)) + { + ++i; + } + } + + g_pack_profile.enabled = enabled; + } + + SAFE_FREE_GLOBAL(argv); + } + + if (!g_pack_profile.enabled) + { + return; + } + + std::lock_guard lock(g_pack_profile.mutex); + g_pack_profile.current_phase = "startup"; + g_pack_profile.start_time = Clock::now(); + g_pack_profile.markers.push_back(PhaseMarker { + .phase = g_pack_profile.current_phase, + .elapsed_us = 0, + }); + g_pack_profile.WriteReportLocked("initialized"); +} + +bool IsPackProfileEnabled() +{ + return g_pack_profile.enabled; +} + +void MarkPackProfilePhase(std::string_view phase) +{ + if (!g_pack_profile.enabled) + { + return; + } + + std::lock_guard lock(g_pack_profile.mutex); + if (g_pack_profile.current_phase == phase) + { + return; + } + + g_pack_profile.current_phase = std::string(phase); + g_pack_profile.markers.push_back(PhaseMarker { + .phase = g_pack_profile.current_phase, + .elapsed_us = CurrentElapsedUs(), + }); + g_pack_profile.WriteReportLocked(PackProfileState::MakePhaseKey("phase", phase)); +} + +void RecordPackProfileMount( + std::string_view format, + std::string_view packPath, + bool ok, + std::size_t entryCount, + std::uint64_t elapsedUs) +{ + if (!g_pack_profile.enabled) + { + return; + } + + std::lock_guard lock(g_pack_profile.mutex); + + auto& formatStats = g_pack_profile.mount_by_format[std::string(format)]; + formatStats.count += 1; + formatStats.failures += ok ? 0 : 1; + formatStats.entry_count += entryCount; + formatStats.elapsed_us += elapsedUs; + + auto& packStats = g_pack_profile.mount_by_pack[PackProfileState::ParsePackLabel(packPath)]; + packStats.count += 1; + packStats.failures += ok ? 0 : 1; + packStats.entry_count += entryCount; + packStats.elapsed_us += elapsedUs; +} + +void RecordPackProfileLoad( + std::string_view format, + std::string_view packPath, + std::string_view requestPath, + bool ok, + std::uint64_t outputBytes, + std::uint64_t elapsedUs) +{ + if (!g_pack_profile.enabled) + { + return; + } + + std::lock_guard lock(g_pack_profile.mutex); + + auto update = [ok, outputBytes, elapsedUs](LoadStats& stats) { + stats.count += 1; + stats.failures += ok ? 0 : 1; + stats.output_bytes += outputBytes; + stats.elapsed_us += elapsedUs; + }; + + update(g_pack_profile.load_by_format[std::string(format)]); + update(g_pack_profile.load_by_phase_format[ + PackProfileState::MakePhaseKey(g_pack_profile.current_phase, format)]); + update(g_pack_profile.load_by_phase_pack[ + PackProfileState::MakePhaseKey(g_pack_profile.current_phase, PackProfileState::ParsePackLabel(packPath))]); + update(g_pack_profile.load_by_extension[PackProfileState::ParseExtension(requestPath)]); +} + +void RecordPackProfileStage( + std::string_view format, + std::string_view stage, + std::uint64_t inputBytes, + std::uint64_t outputBytes, + std::uint64_t elapsedUs) +{ + if (!g_pack_profile.enabled) + { + return; + } + + std::lock_guard lock(g_pack_profile.mutex); + auto& stats = g_pack_profile.stage_by_key[ + PackProfileState::MakePhaseKey(format, stage)]; + stats.count += 1; + stats.input_bytes += inputBytes; + stats.output_bytes += outputBytes; + stats.elapsed_us += elapsedUs; +} + +void FlushPackProfileSnapshot(std::string_view reason) +{ + if (!g_pack_profile.enabled) + { + return; + } + + std::lock_guard lock(g_pack_profile.mutex); + g_pack_profile.WriteReportLocked(reason); +} diff --git a/src/PackLib/PackProfile.h b/src/PackLib/PackProfile.h new file mode 100644 index 0000000..e89c742 --- /dev/null +++ b/src/PackLib/PackProfile.h @@ -0,0 +1,29 @@ +#pragma once + +#include +#include +#include + +void InitializePackProfile(const char* commandLine); +bool IsPackProfileEnabled(); +void MarkPackProfilePhase(std::string_view phase); +void RecordPackProfileMount( + std::string_view format, + std::string_view packPath, + bool ok, + std::size_t entryCount, + std::uint64_t elapsedUs); +void RecordPackProfileLoad( + std::string_view format, + std::string_view packPath, + std::string_view requestPath, + bool ok, + std::uint64_t outputBytes, + std::uint64_t elapsedUs); +void RecordPackProfileStage( + std::string_view format, + std::string_view stage, + std::uint64_t inputBytes, + std::uint64_t outputBytes, + std::uint64_t elapsedUs); +void FlushPackProfileSnapshot(std::string_view reason); diff --git a/src/UserInterface/PythonNetworkStreamPhaseGame.cpp b/src/UserInterface/PythonNetworkStreamPhaseGame.cpp index 5fbae95..26b1bf1 100644 --- a/src/UserInterface/PythonNetworkStreamPhaseGame.cpp +++ b/src/UserInterface/PythonNetworkStreamPhaseGame.cpp @@ -20,6 +20,7 @@ #include "PythonApplication.h" #include "GameLib/ItemManager.h" +#include "PackLib/PackProfile.h" #include "AbstractApplication.h" #include "AbstractCharacterManager.h" @@ -414,6 +415,7 @@ void CPythonNetworkStream::SetGamePhase() if ("Game"!=m_strPhase) m_phaseLeaveFunc.Run(); + MarkPackProfilePhase("game"); m_strPhase = "Game"; m_dwChangingPhaseTime = ELTimer_GetMSec(); diff --git a/src/UserInterface/PythonNetworkStreamPhaseLoading.cpp b/src/UserInterface/PythonNetworkStreamPhaseLoading.cpp index 02f43a4..3addc87 100644 --- a/src/UserInterface/PythonNetworkStreamPhaseLoading.cpp +++ b/src/UserInterface/PythonNetworkStreamPhaseLoading.cpp @@ -5,6 +5,7 @@ #include "NetworkActorManager.h" #include "AbstractPlayer.h" #include "PackLib/PackManager.h" +#include "PackLib/PackProfile.h" void CPythonNetworkStream::EnableChatInsultFilter(bool isEnable) { @@ -90,6 +91,7 @@ void CPythonNetworkStream::SetLoadingPhase() Tracen(""); Tracen("## Network - Loading Phase ##"); Tracen(""); + MarkPackProfilePhase("loading"); m_strPhase = "Loading"; diff --git a/src/UserInterface/PythonNetworkStreamPhaseLogin.cpp b/src/UserInterface/PythonNetworkStreamPhaseLogin.cpp index 9a876ed..c7c0448 100644 --- a/src/UserInterface/PythonNetworkStreamPhaseLogin.cpp +++ b/src/UserInterface/PythonNetworkStreamPhaseLogin.cpp @@ -2,6 +2,7 @@ #include "PythonNetworkStream.h" #include "Packet.h" #include "AccountConnector.h" +#include "PackLib/PackProfile.h" // Login --------------------------------------------------------------------------- void CPythonNetworkStream::LoginPhase() @@ -18,6 +19,7 @@ void CPythonNetworkStream::SetLoginPhase() Tracen(""); Tracen("## Network - Login Phase ##"); Tracen(""); + MarkPackProfilePhase("login"); m_strPhase = "Login";