From 181e4833e2e23d4ca172f4b898f58b92f8a45cf1 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Tue, 14 Jan 2025 20:08:47 +0200 Subject: [PATCH 01/24] Base implementation of profiler to improve / work on. --- src/xrScriptEngine/CMakeLists.txt | 2 + src/xrScriptEngine/ScriptEngineScript.cpp | 40 +++ src/xrScriptEngine/script_debugger.cpp | 6 +- src/xrScriptEngine/script_engine.cpp | 14 + src/xrScriptEngine/script_engine.hpp | 3 + src/xrScriptEngine/script_profiler.cpp | 248 ++++++++++++++++++ src/xrScriptEngine/script_profiler.hpp | 89 +++++++ src/xrScriptEngine/xrScriptEngine.vcxproj | 2 + .../xrScriptEngine.vcxproj.filters | 6 + 9 files changed, 407 insertions(+), 3 deletions(-) create mode 100644 src/xrScriptEngine/script_profiler.cpp create mode 100644 src/xrScriptEngine/script_profiler.hpp diff --git a/src/xrScriptEngine/CMakeLists.txt b/src/xrScriptEngine/CMakeLists.txt index ead48c5ce2b..cb6e6121033 100644 --- a/src/xrScriptEngine/CMakeLists.txt +++ b/src/xrScriptEngine/CMakeLists.txt @@ -14,6 +14,8 @@ target_sources_grouped( script_debugger_threads.hpp script_lua_helper.cpp script_lua_helper.hpp + script_profiler.cpp, + script_profiler.hpp, ) target_sources_grouped( diff --git a/src/xrScriptEngine/ScriptEngineScript.cpp b/src/xrScriptEngine/ScriptEngineScript.cpp index ad0303425f9..2bd3499ab81 100644 --- a/src/xrScriptEngine/ScriptEngineScript.cpp +++ b/src/xrScriptEngine/ScriptEngineScript.cpp @@ -66,6 +66,36 @@ bool is_editor() return GEnv.ScriptEngine->is_editor(); } +void isProfilerActive() +{ + GEnv.ScriptEngine->m_profiler->isActive(); +} + +void startProfiler() +{ + GEnv.ScriptEngine->m_profiler->start(); +} + +void stopProfiler() +{ + GEnv.ScriptEngine->m_profiler->stop(); +} + +void resetProfiler() +{ + GEnv.ScriptEngine->m_profiler->reset(); +} + +void saveProfiler() +{ + GEnv.ScriptEngine->m_profiler->save(); +} + +void logProfiler() +{ + GEnv.ScriptEngine->m_profiler->log(); +} + inline int bit_and(const int i, const int j) { return i & j; } inline int bit_or(const int i, const int j) { return i | j; } inline int bit_xor(const int i, const int j) { return i ^ j; } @@ -164,4 +194,14 @@ SCRIPT_EXPORT(CScriptEngine, (), def("editor", &is_editor), def("user_name", &user_name) ]; + + module(luaState, "profiler") + [ + def("isActive", &isProfilerActive), + def("start", &startProfiler), + def("stop", &stopProfiler), + def("reset", &resetProfiler), + def("log", &logProfiler), + def("save", &saveProfiler) + ]; }); diff --git a/src/xrScriptEngine/script_debugger.cpp b/src/xrScriptEngine/script_debugger.cpp index 0e5020ec68f..2f285a84b56 100644 --- a/src/xrScriptEngine/script_debugger.cpp +++ b/src/xrScriptEngine/script_debugger.cpp @@ -114,9 +114,9 @@ BOOL CScriptDebugger::Active() { return m_bIdePresent; } CScriptDebugger::CScriptDebugger(CScriptEngine* scriptEngine) { this->scriptEngine = scriptEngine; - m_threads = new CDbgScriptThreads(scriptEngine, this); - m_callStack = new CScriptCallStack(this); - m_lua = new CDbgLuaHelper(this); + m_threads = xr_new(scriptEngine, this); + m_callStack = xr_new(this); + m_lua = xr_new(this); ZeroMemory(m_curr_connected_mslot, sizeof(m_curr_connected_mslot)); // m_pDebugger = this; m_nLevel = 0; diff --git a/src/xrScriptEngine/script_engine.cpp b/src/xrScriptEngine/script_engine.cpp index e5d725a0f0d..1e787d51bf4 100644 --- a/src/xrScriptEngine/script_engine.cpp +++ b/src/xrScriptEngine/script_engine.cpp @@ -9,6 +9,7 @@ #include "pch.hpp" #include "script_engine.hpp" #include "script_process.hpp" +#include "script_profiler.hpp" #include "script_thread.hpp" #include "ScriptExporter.hpp" #include "BindingsDumper.hpp" @@ -769,6 +770,7 @@ CScriptEngine::CScriptEngine(bool is_editor) #endif #endif m_is_editor = is_editor; + m_profiler = xr_new(); } CScriptEngine::~CScriptEngine() @@ -789,6 +791,8 @@ CScriptEngine::~CScriptEngine() #endif if (scriptBuffer) xr_free(scriptBuffer); + + xr_free(m_profiler); } void CScriptEngine::unload() @@ -878,11 +882,15 @@ void CScriptEngine::lua_hook_call(lua_State* L, lua_Debug* dbg) { CScriptEngine* scriptEngine = GetInstance(L); VERIFY(scriptEngine); + if (scriptEngine->current_thread()) scriptEngine->current_thread()->script_hook(L, dbg); else scriptEngine->m_stack_is_ready = true; + + scriptEngine->m_profiler->onLuaHookCall(L, dbg); } + #endif int CScriptEngine::auto_load(lua_State* L) @@ -1060,6 +1068,12 @@ void CScriptEngine::init(ExporterFunc exporterFunc, bool loadGlobalNamespace) m_reload_modules = save; } m_stack_level = lua_gettop(lua()); + + // todo: Hook on activation wich check. + // todo: Hook on activation wich check. + // todo: Hook on activation wich check. + lua_sethook(lua(), CScriptEngine::lua_hook_call, LUA_MASKLINE | LUA_MASKCALL | LUA_MASKRET, 0); + setvbuf(stderr, g_ca_stdout, _IOFBF, sizeof(g_ca_stdout)); } diff --git a/src/xrScriptEngine/script_engine.hpp b/src/xrScriptEngine/script_engine.hpp index 8da5f8e49f3..f91a61a7b5e 100644 --- a/src/xrScriptEngine/script_engine.hpp +++ b/src/xrScriptEngine/script_engine.hpp @@ -10,6 +10,7 @@ #include "xrCore/xrCore.h" #include "xrScriptEngine/xrScriptEngine.hpp" #include "xrScriptEngine/ScriptExporter.hpp" +#include "xrScriptEngine/script_profiler.hpp" #include "xrScriptEngine/script_space_forward.hpp" #include "xrScriptEngine/Functor.hpp" #include "xrCore/Threading/Lock.hpp" @@ -153,6 +154,8 @@ class XRSCRIPTENGINE_API CScriptEngine } public: + CScriptProfiler* m_profiler; + lua_State* lua() { return m_virtual_machine; } void current_thread(CScriptThread* thread) { diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp new file mode 100644 index 00000000000..f28d1fd59da --- /dev/null +++ b/src/xrScriptEngine/script_profiler.cpp @@ -0,0 +1,248 @@ +#include "pch.hpp" +#include "script_profiler.hpp" + +CScriptProfiler::CScriptProfiler() +{ + m_active = false; + m_profile_level = 1; + + // todo: Configuration of profile levels. + // todo: Configuration of profile levels. + // todo: Configuration of profile levels. + + if (strstr(Core.Params, "-lua_profiler")) + { + start(); + } +} + +CScriptProfiler::~CScriptProfiler() +{ +} + +void CScriptProfiler::start() +{ + if (m_active) + { + Msg("Tried to start active profiler, operation ignored"); + return; + } + + Msg("Starting lua scripts profiler"); + + m_active = true; + + // todo: Reset? + // todo: Reset? + // todo: Reset? + + // todo: Check JIT and warn? Allow turn it off with parameter? + // todo: Check JIT and warn? Allow turn it off with parameter? + // todo: Check JIT and warn? Allow turn it off with parameter? + + // todo: Attach hook? + // todo: Attach hook? + // todo: Attach hook? +} + +void CScriptProfiler::stop() +{ + if (!m_active) + { + Msg("Tried to stop inactive profiler, operation ignored"); + return; + } + + Msg("Stopping lua scripts profiler"); + + // todo: Reset? + // todo: Reset? + // todo: Reset? + + // todo: Detach hook? + // todo: Detach hook? + // todo: Detach hook? +} + +void CScriptProfiler::reset() +{ + Msg("Reset profiler"); + + // todo; + // todo; + // todo; +} + +void CScriptProfiler::log() +{ + + u64 total_count = 0; + u64 total_duration = 0; + + std::vector entries; + entries.reserve(m_profiling_portions.size()); + + for (auto it = m_profiling_portions.begin(); it != m_profiling_portions.end(); it++) + { + entries.push_back(it); + + total_count += it->second.count(); + total_duration += it->second.duration(); + } + + + Msg("=================================================================="); + Msg("= Log profiler report, %d entries", entries.size()); + Msg("=================================================================="); + Msg("= By calls duration:"); + Msg("===="); + + u64 index = 0; + string512 buffer; + + std::sort(entries.begin(), entries.end(), + [](auto& left, auto& right) { return left->second.duration() > right->second.duration(); }); + + for (auto it = entries.begin(); it != entries.end(); it++) + { + if (index >= CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT) + break; + + Msg("[%3d] %6.3f ms (%5.2f%%) %6d calls, %6.3f ms avg : %s", index, (*it)->second.duration() / 1000.0, + ((f64)(*it)->second.duration() * 100.0) / (f64)total_duration, (*it)->second.count(), + (f64)(*it)->second.duration() / (f64)(*it)->second.count() / 1000.0, + (*it)->first.c_str()); + + index += 1; + } + + Msg("=================================================================="); + Msg("= By calls count:"); + Msg("===="); + + index = 0; + + std::sort(entries.begin(), entries.end(), + [](auto& left, auto& right) { return left->second.count() > right->second.count(); }); + + for (auto it = entries.begin(); it != entries.end(); it++) + { + if (index >= CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT) + break; + + Msg("[%3d] %6d (%5.2f%%) : %s", index, (*it)->second.count(), + ((f64)(*it)->second.count() * 100.0) / (f64)total_count, (*it)->first.c_str()); + + index += 1; + } + + Msg("=================================================================="); + Msg("= Total function calls count: %d", total_count); + Msg("= Total function calls duration: %f ms", (f32) total_duration / 1000.0); + Msg("=================================================================="); + + FlushLog(); + + // todo; + // todo; + // todo; +} + +void CScriptProfiler::save() +{ + Log("Save profiler report"); + + // todo; + // todo; + // todo; +} + +void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) +{ + if (!m_active || dbg->event == LUA_HOOKLINE) + return; + + lua_Debug parent_stack_info; + lua_Debug stack_info; + + // Check higher level of stack. + if (m_profile_level > 0) + { + if (!lua_getstack(L, 1, &parent_stack_info)) + { + return; + } + + lua_getinfo(L, "nSl", &parent_stack_info); + } + + if (!lua_getstack(L, 0, &stack_info)) + { + return; + } + + lua_getinfo(L, "nSl", &stack_info); + + string512 buffer; + + auto name = stack_info.name ? stack_info.name : "?"; + auto parent_name = m_profile_level > 0 && parent_stack_info.name ? parent_stack_info.name : "?"; + auto short_src = stack_info.short_src; + auto line_defined = stack_info.linedefined; + + if (!stack_info.name && line_defined == 0) + name = "lua-script-body"; + + // Include date from higher stack levels. + if (m_profile_level > 0) + xr_sprintf(buffer, "%s [%d] - %s @ %s", name, line_defined, parent_name, short_src); + else + xr_sprintf(buffer, "%s [%d] @ %s", name, line_defined, parent_name, short_src); + + auto it = m_profiling_portions.find(buffer); + bool exists = it != m_profiling_portions.end(); + + switch (dbg->event) + { + case LUA_HOOKCALL: + { + if (exists) + { + it->second.start(); + } + else + { + CScriptProfilerPortion portion; + + portion.start(); + + m_profiling_portions.emplace(buffer, std::move(portion)); + } + + return; + } + case LUA_HOOKRET: + { + if (exists) + { + it->second.stop(); + } + + return; + } + case LUA_HOOKTAILRET: + { + if (exists) + { + it->second.stop(); + } + + return; + } + default: NODEFAULT; + } +} + +// todo: Add util to get frame info +// todo: Add util to get frame info +// todo: Add util to get frame info diff --git a/src/xrScriptEngine/script_profiler.hpp b/src/xrScriptEngine/script_profiler.hpp new file mode 100644 index 00000000000..368cb070658 --- /dev/null +++ b/src/xrScriptEngine/script_profiler.hpp @@ -0,0 +1,89 @@ +#pragma once + +#include "pch.hpp" +#include "xrCommon/xr_unordered_map.h" + +struct lua_State; +struct lua_Debug; + +class CScriptProfilerPortion { + using Clock = std::chrono::high_resolution_clock; + using Time = Clock::time_point; + using Duration = Clock::duration; + + private: + u64 m_calls_count; + u32 m_calls_active; + + Time m_started_at; + Duration m_duration; + + public: + CScriptProfilerPortion(): m_calls_count(0), m_calls_active(0), m_duration(0), m_started_at() {} + + void start() + { + m_calls_count += 1; + + if (m_calls_active) + { + m_calls_active += 1; + return; + } + else + { + m_started_at = Clock::now(); + m_calls_active += 1; + } + } + + void stop() + { + if (!m_calls_active) + return; + + m_calls_active -= 1; + + if (m_calls_active) + return; + + const auto now = Clock::now(); + + if (now > m_started_at) + m_duration += now - m_started_at; + } + + u64 count() const { return m_calls_count; } + + u64 duration() const + { + using namespace std::chrono; + return u64(duration_cast(m_duration).count()); + } +}; + +class XRSCRIPTENGINE_API CScriptProfiler +{ +private: + static const u32 PROFILE_ENTRIES_LOG_LIMIT = 128; + + // Profiling level - number of stacks to check before each function call. + // Helps validating results of same functions called from different places vs totals by specific function. + u8 m_profile_level; + bool m_active; + xr_unordered_map m_profiling_portions; + +public: + CScriptProfiler(); + virtual ~CScriptProfiler(); + + bool isActive() const { return m_active; }; + + void start(); + void stop(); + void reset(); + void log(); + void save(); + + void onLuaHookCall(lua_State* L, lua_Debug* dbg); +}; diff --git a/src/xrScriptEngine/xrScriptEngine.vcxproj b/src/xrScriptEngine/xrScriptEngine.vcxproj index 2d2521c36e3..4fdbd3bd804 100644 --- a/src/xrScriptEngine/xrScriptEngine.vcxproj +++ b/src/xrScriptEngine/xrScriptEngine.vcxproj @@ -50,6 +50,7 @@ + @@ -68,6 +69,7 @@ + diff --git a/src/xrScriptEngine/xrScriptEngine.vcxproj.filters b/src/xrScriptEngine/xrScriptEngine.vcxproj.filters index b774e488542..57b22e7e030 100644 --- a/src/xrScriptEngine/xrScriptEngine.vcxproj.filters +++ b/src/xrScriptEngine/xrScriptEngine.vcxproj.filters @@ -45,6 +45,9 @@ Debug + + Debug + Debug @@ -143,6 +146,9 @@ Debug + + Debug + Process From 2cb392809b7a841ec2cd01092b30d19dd2f3143d Mon Sep 17 00:00:00 2001 From: Neloreck Date: Tue, 14 Jan 2025 20:29:22 +0200 Subject: [PATCH 02/24] Remove not needed spaces. --- src/xrScriptEngine/script_profiler.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index f28d1fd59da..5a5258ac57a 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -178,7 +178,7 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) if (!lua_getstack(L, 0, &stack_info)) { - return; + return; } lua_getinfo(L, "nSl", &stack_info); @@ -221,7 +221,7 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) return; } - case LUA_HOOKRET: + case LUA_HOOKRET: { if (exists) { From 8a2c7ac9e3f89a6c47e9575ccd7adb16268005ea Mon Sep 17 00:00:00 2001 From: Neloreck Date: Wed, 15 Jan 2025 03:20:21 +0200 Subject: [PATCH 03/24] Fix cmake list. Use profiler by value, remove allocation. Do not attach hook by default, use original logics for script engine, add attach methods. Update profiler exports, add profiler type global variables. Add profiler type separation / additional methods for hook/jit based profiling. Separate env vars for different profiling. --- src/xrScriptEngine/CMakeLists.txt | 4 +- src/xrScriptEngine/ScriptEngineScript.cpp | 68 +++++----- src/xrScriptEngine/script_engine.cpp | 12 +- src/xrScriptEngine/script_engine.hpp | 2 +- src/xrScriptEngine/script_profiler.cpp | 158 +++++++++++++++++----- src/xrScriptEngine/script_profiler.hpp | 36 ++++- 6 files changed, 192 insertions(+), 88 deletions(-) diff --git a/src/xrScriptEngine/CMakeLists.txt b/src/xrScriptEngine/CMakeLists.txt index cb6e6121033..5ce29f29e17 100644 --- a/src/xrScriptEngine/CMakeLists.txt +++ b/src/xrScriptEngine/CMakeLists.txt @@ -14,8 +14,8 @@ target_sources_grouped( script_debugger_threads.hpp script_lua_helper.cpp script_lua_helper.hpp - script_profiler.cpp, - script_profiler.hpp, + script_profiler.cpp + script_profiler.hpp ) target_sources_grouped( diff --git a/src/xrScriptEngine/ScriptEngineScript.cpp b/src/xrScriptEngine/ScriptEngineScript.cpp index 2bd3499ab81..5c7bab48833 100644 --- a/src/xrScriptEngine/ScriptEngineScript.cpp +++ b/src/xrScriptEngine/ScriptEngineScript.cpp @@ -66,36 +66,6 @@ bool is_editor() return GEnv.ScriptEngine->is_editor(); } -void isProfilerActive() -{ - GEnv.ScriptEngine->m_profiler->isActive(); -} - -void startProfiler() -{ - GEnv.ScriptEngine->m_profiler->start(); -} - -void stopProfiler() -{ - GEnv.ScriptEngine->m_profiler->stop(); -} - -void resetProfiler() -{ - GEnv.ScriptEngine->m_profiler->reset(); -} - -void saveProfiler() -{ - GEnv.ScriptEngine->m_profiler->save(); -} - -void logProfiler() -{ - GEnv.ScriptEngine->m_profiler->log(); -} - inline int bit_and(const int i, const int j) { return i & j; } inline int bit_or(const int i, const int j) { return i | j; } inline int bit_xor(const int i, const int j) { return i ^ j; } @@ -169,6 +139,10 @@ std::ostream& operator<<(std::ostream& os, const profile_timer_script& pt) { ret SCRIPT_EXPORT(CScriptEngine, (), { using namespace luabind; + + globals(luaState) ["PROFILER_TYPE_HOOK"] = (u32) CScriptProfilerType::Hook; + globals(luaState) ["PROFILER_TYPE_JIT"] = (u32) CScriptProfilerType::Jit; + module(luaState) [ class_("profile_timer") @@ -197,11 +171,33 @@ SCRIPT_EXPORT(CScriptEngine, (), module(luaState, "profiler") [ - def("isActive", &isProfilerActive), - def("start", &startProfiler), - def("stop", &stopProfiler), - def("reset", &resetProfiler), - def("log", &logProfiler), - def("save", &saveProfiler) + def("is_active", +[]() + { + GEnv.ScriptEngine->m_profiler.isActive(); + }), + def("start", +[]() + { + GEnv.ScriptEngine->m_profiler.start(); + }), + def("start", +[](CScriptProfilerType hook_type) + { + GEnv.ScriptEngine->m_profiler.start(hook_type); + }), + def("stop", +[]() + { + GEnv.ScriptEngine->m_profiler.stop(); + }), + def("reset", +[]() + { + GEnv.ScriptEngine->m_profiler.reset(); + }), + def("log_report", +[]() + { + GEnv.ScriptEngine->m_profiler.logReport(); + }), + def("save_report", +[]() + { + GEnv.ScriptEngine->m_profiler.saveReport(); + }) ]; }); diff --git a/src/xrScriptEngine/script_engine.cpp b/src/xrScriptEngine/script_engine.cpp index 1e787d51bf4..2872348766a 100644 --- a/src/xrScriptEngine/script_engine.cpp +++ b/src/xrScriptEngine/script_engine.cpp @@ -748,7 +748,7 @@ void CScriptEngine::disconnect_from_debugger() } #endif -CScriptEngine::CScriptEngine(bool is_editor) +CScriptEngine::CScriptEngine(bool is_editor) : m_profiler(this) { luabind::allocator = &luabind_allocator; luabind::allocator_context = nullptr; @@ -770,7 +770,6 @@ CScriptEngine::CScriptEngine(bool is_editor) #endif #endif m_is_editor = is_editor; - m_profiler = xr_new(); } CScriptEngine::~CScriptEngine() @@ -791,8 +790,6 @@ CScriptEngine::~CScriptEngine() #endif if (scriptBuffer) xr_free(scriptBuffer); - - xr_free(m_profiler); } void CScriptEngine::unload() @@ -888,7 +885,7 @@ void CScriptEngine::lua_hook_call(lua_State* L, lua_Debug* dbg) else scriptEngine->m_stack_is_ready = true; - scriptEngine->m_profiler->onLuaHookCall(L, dbg); + scriptEngine->m_profiler.onLuaHookCall(L, dbg); } #endif @@ -1069,11 +1066,6 @@ void CScriptEngine::init(ExporterFunc exporterFunc, bool loadGlobalNamespace) } m_stack_level = lua_gettop(lua()); - // todo: Hook on activation wich check. - // todo: Hook on activation wich check. - // todo: Hook on activation wich check. - lua_sethook(lua(), CScriptEngine::lua_hook_call, LUA_MASKLINE | LUA_MASKCALL | LUA_MASKRET, 0); - setvbuf(stderr, g_ca_stdout, _IOFBF, sizeof(g_ca_stdout)); } diff --git a/src/xrScriptEngine/script_engine.hpp b/src/xrScriptEngine/script_engine.hpp index f91a61a7b5e..8344428594a 100644 --- a/src/xrScriptEngine/script_engine.hpp +++ b/src/xrScriptEngine/script_engine.hpp @@ -154,7 +154,7 @@ class XRSCRIPTENGINE_API CScriptEngine } public: - CScriptProfiler* m_profiler; + CScriptProfiler m_profiler; lua_State* lua() { return m_virtual_machine; } void current_thread(CScriptThread* thread) diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index 5a5258ac57a..bae820ff27f 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -1,26 +1,34 @@ #include "pch.hpp" #include "script_profiler.hpp" +#include "xrScriptEngine/script_engine.hpp" -CScriptProfiler::CScriptProfiler() +CScriptProfiler::CScriptProfiler(CScriptEngine* engine) { + R_ASSERT(engine != NULL); + + m_engine = engine; + m_active = false; m_profile_level = 1; + m_profiler_type = CScriptProfilerType::None; - // todo: Configuration of profile levels. - // todo: Configuration of profile levels. - // todo: Configuration of profile levels. + // todo: Configuration of profile levels for hook profiler. + // todo: Configuration of profile levels for hook profiler. + // todo: Configuration of profile levels for hook profiler. if (strstr(Core.Params, "-lua_profiler")) - { start(); - } + else if (strstr(Core.Params, "-lua_hook_profiler")) + start(CScriptProfilerType::Hook); + else if (strstr(Core.Params, "-lua_jit_profiler")) + start(CScriptProfilerType::Jit); } CScriptProfiler::~CScriptProfiler() { } -void CScriptProfiler::start() +void CScriptProfiler::start(CScriptProfilerType profiler_type) { if (m_active) { @@ -28,58 +36,107 @@ void CScriptProfiler::start() return; } - Msg("Starting lua scripts profiler"); - - m_active = true; - - // todo: Reset? - // todo: Reset? - // todo: Reset? + if (profiler_type == CScriptProfilerType::None) + { + Msg("Tried to start none profiler type"); + return; + } // todo: Check JIT and warn? Allow turn it off with parameter? // todo: Check JIT and warn? Allow turn it off with parameter? // todo: Check JIT and warn? Allow turn it off with parameter? - // todo: Attach hook? - // todo: Attach hook? - // todo: Attach hook? + m_profiling_portions.clear(); + m_active = true; + m_profiler_type = profiler_type; + + switch (profiler_type) + { + case CScriptProfilerType::Hook: + Msg("Starting lua scripts hook profiler"); + + attachLuaHook(); + + return; + case CScriptProfilerType::Jit: + { + Msg("Starting lua scripts jit profiler"); + + return; + } + + default: NODEFAULT; + } } void CScriptProfiler::stop() { if (!m_active) { - Msg("Tried to stop inactive profiler, operation ignored"); + Msg("Tried to stop inactive profiler"); + return; + } + + if (m_profiler_type == CScriptProfilerType::None) + { + Msg("Tried to stop none profiler type"); return; } - Msg("Stopping lua scripts profiler"); + switch (m_profiler_type) + { + case CScriptProfilerType::Hook: + Msg("Stopping lua scripts hook profiler"); + + // Do not detach hook here, adding it means that it is already test run in the first place. + + break; + case CScriptProfilerType::Jit: + { + Msg("Stopping lua scripts jit profiler"); + + break; + } - // todo: Reset? - // todo: Reset? - // todo: Reset? + default: NODEFAULT; + } - // todo: Detach hook? - // todo: Detach hook? - // todo: Detach hook? + m_active = false; } void CScriptProfiler::reset() { Msg("Reset profiler"); - // todo; - // todo; - // todo; + m_profiling_portions.clear(); +} + +void CScriptProfiler::logReport() +{ + switch (m_profiler_type) + { + case CScriptProfilerType::Hook: + return logHookReport(); + case CScriptProfilerType::Jit: + return logJitReport(); + default: + Msg("Nothing to report for profiler"); + return; + } } -void CScriptProfiler::log() +void CScriptProfiler::logHookReport() { + if (m_profiling_portions.empty()) + { + Msg("Nothing to report for hook profiler, data is missing"); + return; + } u64 total_count = 0; u64 total_duration = 0; - std::vector entries; + xr_vector entries; entries.reserve(m_profiling_portions.size()); for (auto it = m_profiling_portions.begin(); it != m_profiling_portions.end(); it++) @@ -90,9 +147,8 @@ void CScriptProfiler::log() total_duration += it->second.duration(); } - Msg("=================================================================="); - Msg("= Log profiler report, %d entries", entries.size()); + Msg("= Log hook profiler report, %d entries", entries.size()); Msg("=================================================================="); Msg("= By calls duration:"); Msg("===="); @@ -148,7 +204,14 @@ void CScriptProfiler::log() // todo; } -void CScriptProfiler::save() +void CScriptProfiler::logJitReport() +{ + // todo; + // todo; + // todo; +} + +void CScriptProfiler::saveReport() { Log("Save profiler report"); @@ -157,6 +220,25 @@ void CScriptProfiler::save() // todo; } +void CScriptProfiler::attachLuaHook() +{ + lua_State* L = lua(); + lua_Hook hook = lua_gethook(L); + + if (hook) + { + if (hook != CScriptEngine::lua_hook_call) + { + Msg("Warning: hook already defined by something else, cannot take ownership as CScriptEngine"); + } + } + else + { + Msg("Attaching lua scripts hook"); + lua_sethook(L, CScriptEngine::lua_hook_call, LUA_MASKLINE | LUA_MASKCALL | LUA_MASKRET, 0); + } +} + void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) { if (!m_active || dbg->event == LUA_HOOKLINE) @@ -243,6 +325,16 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) } } +lua_State* CScriptProfiler::lua() const +{ + return this->m_engine->lua(); +} + +bool CScriptProfiler::luaIsJitProfilerDefined(lua_State* L) +{ + return true; +} + // todo: Add util to get frame info // todo: Add util to get frame info // todo: Add util to get frame info diff --git a/src/xrScriptEngine/script_profiler.hpp b/src/xrScriptEngine/script_profiler.hpp index 368cb070658..29a17cd224c 100644 --- a/src/xrScriptEngine/script_profiler.hpp +++ b/src/xrScriptEngine/script_profiler.hpp @@ -62,28 +62,52 @@ class CScriptProfilerPortion { } }; +enum class CScriptProfilerType : u32 +{ + None = 0, + Hook = 1, + Jit = 2, +}; + class XRSCRIPTENGINE_API CScriptProfiler { + using Clock = std::chrono::high_resolution_clock; + using Time = Clock::time_point; + using Duration = Clock::duration; + private: static const u32 PROFILE_ENTRIES_LOG_LIMIT = 128; - + + CScriptEngine* m_engine; + + bool m_active; + // Profiling level - number of stacks to check before each function call. // Helps validating results of same functions called from different places vs totals by specific function. u8 m_profile_level; - bool m_active; + CScriptProfilerType m_profiler_type; xr_unordered_map m_profiling_portions; public: - CScriptProfiler(); + CScriptProfiler(CScriptEngine* engine); virtual ~CScriptProfiler(); bool isActive() const { return m_active; }; - void start(); + void start(CScriptProfilerType profiler_type = CScriptProfilerType::Hook); void stop(); void reset(); - void log(); - void save(); + void logReport(); + void logHookReport(); + void logJitReport(); + void saveReport(); + + void attachLuaHook(); void onLuaHookCall(lua_State* L, lua_Debug* dbg); + +private: + lua_State* lua() const; + + static bool luaIsJitProfilerDefined(lua_State* L); }; From f6acd964664210a35c02b3df371a93524b7cc24c Mon Sep 17 00:00:00 2001 From: Neloreck Date: Wed, 15 Jan 2025 03:29:29 +0200 Subject: [PATCH 04/24] Add placeholder profiler.script. --- res/gamedata/scripts/profiler.script | 11 +++++++++++ src/xrScriptEngine/script_profiler.cpp | 4 ++-- 2 files changed, 13 insertions(+), 2 deletions(-) create mode 100644 res/gamedata/scripts/profiler.script diff --git a/res/gamedata/scripts/profiler.script b/res/gamedata/scripts/profiler.script new file mode 100644 index 00000000000..26eb4d733c1 --- /dev/null +++ b/res/gamedata/scripts/profiler.script @@ -0,0 +1,11 @@ +-- Original profiler was not working and caused game to crash when jit parameter is disabled. +-- For safety reasons there is mock setup function and empty module without original code. +-- +-- 1) LUA does not allow setting up multiple hooks, adding hooks here instead of C++ codebase is problematic +-- 2) Luabind/Luajit already injects complex logics, C++ codebase adds error callbacks and custom logics. +-- As result, stack and state may be corrupted and cause random logics/memory errors. +-- +-- See: https://github.com/OpenXRay/xray-16/issues/1436 + +-- Mock placeholder. +function setup_hook() end diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index bae820ff27f..e1974bf44d7 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -104,8 +104,8 @@ void CScriptProfiler::stop() m_active = false; } -void CScriptProfiler::reset() -{ +void CScriptProfiler::reset() +{ Msg("Reset profiler"); m_profiling_portions.clear(); From 5c96778ea89a7b8f2670fafc34cc9ba0bbf5d671 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Thu, 16 Jan 2025 05:53:07 +0200 Subject: [PATCH 05/24] Implemented core for sampling profiler with luajit built-in methods. --- src/xrGame/ai_space.cpp | 2 +- src/xrScriptEngine/ScriptEngineScript.cpp | 16 +- src/xrScriptEngine/script_engine.cpp | 33 ++- src/xrScriptEngine/script_engine.hpp | 6 +- src/xrScriptEngine/script_profiler.cpp | 323 +++++++++++++++++----- src/xrScriptEngine/script_profiler.hpp | 26 +- src/xrScriptEngine/xrScriptEngine.hpp | 1 + 7 files changed, 310 insertions(+), 97 deletions(-) diff --git a/src/xrGame/ai_space.cpp b/src/xrGame/ai_space.cpp index aef1fd71c32..74dfe403e9e 100644 --- a/src/xrGame/ai_space.cpp +++ b/src/xrGame/ai_space.cpp @@ -50,7 +50,7 @@ void CAI_Space::init() m_moving_objects = xr_make_unique<::moving_objects>(); VERIFY(!GEnv.ScriptEngine); - GEnv.ScriptEngine = xr_new(); + GEnv.ScriptEngine = xr_new(false, true); RestartScriptEngine(); } diff --git a/src/xrScriptEngine/ScriptEngineScript.cpp b/src/xrScriptEngine/ScriptEngineScript.cpp index 5c7bab48833..4bf842b62a7 100644 --- a/src/xrScriptEngine/ScriptEngineScript.cpp +++ b/src/xrScriptEngine/ScriptEngineScript.cpp @@ -141,7 +141,7 @@ SCRIPT_EXPORT(CScriptEngine, (), using namespace luabind; globals(luaState) ["PROFILER_TYPE_HOOK"] = (u32) CScriptProfilerType::Hook; - globals(luaState) ["PROFILER_TYPE_JIT"] = (u32) CScriptProfilerType::Jit; + globals(luaState) ["PROFILER_TYPE_SAMPLING"] = (u32) CScriptProfilerType::Sampling; module(luaState) [ @@ -173,31 +173,31 @@ SCRIPT_EXPORT(CScriptEngine, (), [ def("is_active", +[]() { - GEnv.ScriptEngine->m_profiler.isActive(); + GEnv.ScriptEngine->m_profiler->isActive(); }), def("start", +[]() { - GEnv.ScriptEngine->m_profiler.start(); + GEnv.ScriptEngine->m_profiler->start(); }), def("start", +[](CScriptProfilerType hook_type) { - GEnv.ScriptEngine->m_profiler.start(hook_type); + GEnv.ScriptEngine->m_profiler->start(hook_type); }), def("stop", +[]() { - GEnv.ScriptEngine->m_profiler.stop(); + GEnv.ScriptEngine->m_profiler->stop(); }), def("reset", +[]() { - GEnv.ScriptEngine->m_profiler.reset(); + GEnv.ScriptEngine->m_profiler->reset(); }), def("log_report", +[]() { - GEnv.ScriptEngine->m_profiler.logReport(); + GEnv.ScriptEngine->m_profiler->logReport(); }), def("save_report", +[]() { - GEnv.ScriptEngine->m_profiler.saveReport(); + GEnv.ScriptEngine->m_profiler->saveReport(); }) ]; }); diff --git a/src/xrScriptEngine/script_engine.cpp b/src/xrScriptEngine/script_engine.cpp index 2872348766a..d0add0eff3a 100644 --- a/src/xrScriptEngine/script_engine.cpp +++ b/src/xrScriptEngine/script_engine.cpp @@ -16,6 +16,9 @@ #ifdef USE_DEBUGGER #include "script_debugger.hpp" #endif +#ifdef DEBUG +#include "script_thread.hpp" +#endif #include #include "Common/Noncopyable.hpp" #include "xrCore/ModuleLookup.hpp" @@ -115,7 +118,10 @@ void CScriptEngine::reinit() stateMapLock.Leave(); if (m_virtual_machine) { - lua_close(m_virtual_machine); + if (m_profiler) + m_profiler->onDispose(m_virtual_machine); + + lua_close(m_virtual_machine); UnregisterState(m_virtual_machine); } m_virtual_machine = lua_newstate(lua_alloc, nullptr); @@ -131,6 +137,9 @@ void CScriptEngine::reinit() file_header = file_header_old; scriptBufferSize = 1024 * 1024; scriptBuffer = xr_alloc(scriptBufferSize); + + if (m_profiler) + m_profiler->onReinit(m_virtual_machine); } void CScriptEngine::print_stack(lua_State* L) @@ -748,13 +757,14 @@ void CScriptEngine::disconnect_from_debugger() } #endif -CScriptEngine::CScriptEngine(bool is_editor) : m_profiler(this) +CScriptEngine::CScriptEngine(bool is_editor, bool is_with_profiler) { luabind::allocator = &luabind_allocator; luabind::allocator_context = nullptr; m_current_thread = nullptr; m_stack_is_ready = false; m_virtual_machine = nullptr; + m_profiler = is_with_profiler ? xr_new(this) : nullptr; m_stack_level = 0; m_reload_modules = false; m_last_no_file_length = 0; @@ -774,6 +784,14 @@ CScriptEngine::CScriptEngine(bool is_editor) : m_profiler(this) CScriptEngine::~CScriptEngine() { + if (m_profiler) + { + if (m_virtual_machine) + m_profiler->onDispose(m_virtual_machine); + + xr_delete(m_profiler); + } + if (m_virtual_machine) lua_close(m_virtual_machine); while (!m_script_processes.empty()) @@ -872,24 +890,22 @@ void CScriptEngine::setup_callbacks() lua_atpanic(lua(), CScriptEngine::lua_panic); } -#ifdef DEBUG -#include "script_thread.hpp" - void CScriptEngine::lua_hook_call(lua_State* L, lua_Debug* dbg) { CScriptEngine* scriptEngine = GetInstance(L); VERIFY(scriptEngine); + #ifdef DEBUG if (scriptEngine->current_thread()) scriptEngine->current_thread()->script_hook(L, dbg); else scriptEngine->m_stack_is_ready = true; + #endif - scriptEngine->m_profiler.onLuaHookCall(L, dbg); + if (scriptEngine->m_profiler) + scriptEngine->m_profiler->onLuaHookCall(L, dbg); } -#endif - int CScriptEngine::auto_load(lua_State* L) { if (lua_gettop(L) < 2 || !lua_istable(L, 1) || !lua_isstring(L, 2)) @@ -1065,7 +1081,6 @@ void CScriptEngine::init(ExporterFunc exporterFunc, bool loadGlobalNamespace) m_reload_modules = save; } m_stack_level = lua_gettop(lua()); - setvbuf(stderr, g_ca_stdout, _IOFBF, sizeof(g_ca_stdout)); } diff --git a/src/xrScriptEngine/script_engine.hpp b/src/xrScriptEngine/script_engine.hpp index 8344428594a..0fa4e87be8e 100644 --- a/src/xrScriptEngine/script_engine.hpp +++ b/src/xrScriptEngine/script_engine.hpp @@ -154,7 +154,7 @@ class XRSCRIPTENGINE_API CScriptEngine } public: - CScriptProfiler m_profiler; + CScriptProfiler* m_profiler; lua_State* lua() { return m_virtual_machine; } void current_thread(CScriptThread* thread) @@ -221,7 +221,7 @@ class XRSCRIPTENGINE_API CScriptEngine void LogVariable(lua_State* l, pcstr name, int level); using ExporterFunc = XRay::ScriptExporter::Node::ExporterFunc; - CScriptEngine(bool is_editor = false); + CScriptEngine(bool is_editor = false, bool is_with_profiler = false); virtual ~CScriptEngine(); void init(ExporterFunc exporterFunc, bool loadGlobalNamespace); virtual void unload(); @@ -231,9 +231,7 @@ class XRSCRIPTENGINE_API CScriptEngine #if 1 //!XRAY_EXCEPTIONS static void lua_cast_failed(lua_State* L, const luabind::type_id& info); #endif -#ifdef DEBUG static void lua_hook_call(lua_State* L, lua_Debug* dbg); -#endif void setup_callbacks(); bool load_file(const char* scriptName, const char* namespaceName); CScriptProcess* script_process(const ScriptProcessor& process_id) const; diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index e1974bf44d7..23ae4f29557 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -9,60 +9,74 @@ CScriptProfiler::CScriptProfiler(CScriptEngine* engine) m_engine = engine; m_active = false; - m_profile_level = 1; + m_hook_profile_level = 1; m_profiler_type = CScriptProfilerType::None; - // todo: Configuration of profile levels for hook profiler. - // todo: Configuration of profile levels for hook profiler. - // todo: Configuration of profile levels for hook profiler. - if (strstr(Core.Params, "-lua_profiler")) start(); else if (strstr(Core.Params, "-lua_hook_profiler")) start(CScriptProfilerType::Hook); - else if (strstr(Core.Params, "-lua_jit_profiler")) - start(CScriptProfilerType::Jit); + else if (strstr(Core.Params, "-lua_sampling_profiler")) + start(CScriptProfilerType::Sampling); } -CScriptProfiler::~CScriptProfiler() -{ -} +CScriptProfiler::~CScriptProfiler() {} void CScriptProfiler::start(CScriptProfilerType profiler_type) { if (m_active) { - Msg("Tried to start active profiler, operation ignored"); + Msg("[P] Tried to start already active profiler, operation ignored"); return; } if (profiler_type == CScriptProfilerType::None) { - Msg("Tried to start none profiler type"); + Msg("[P] Tried to start none type profiler"); return; } - // todo: Check JIT and warn? Allow turn it off with parameter? - // todo: Check JIT and warn? Allow turn it off with parameter? - // todo: Check JIT and warn? Allow turn it off with parameter? + if (!lua()) + { + Msg("[P] Activating profiler on lua engine start, waiting init"); - m_profiling_portions.clear(); - m_active = true; - m_profiler_type = profiler_type; + m_profiler_type = profiler_type; + m_active = true; + + return; + } switch (profiler_type) { case CScriptProfilerType::Hook: - Msg("Starting lua scripts hook profiler"); + if (!attachLuaHook()) + { + Msg("[P] Cannot start scripts hook profiler, hook was not set properly"); + return; + } + + Msg("[P] Starting scripts hook profiler"); - attachLuaHook(); + m_profiling_portions.clear(); + m_profiler_type = profiler_type; + m_active = true; return; - case CScriptProfilerType::Jit: + case CScriptProfilerType::Sampling: { - Msg("Starting lua scripts jit profiler"); + if (!luaIsJitProfilerDefined(lua())) + { + Msg("[P] Cannot start scripts sampling profiler, jit.profiler module is not defined"); + return; + } - return; + Msg("[P] Starting scripts sampling profiler"); + luaJitSamplingProfilerAttach(this); + + m_profiler_type = profiler_type; + m_active = true; + + return; } default: NODEFAULT; @@ -73,27 +87,29 @@ void CScriptProfiler::stop() { if (!m_active) { - Msg("Tried to stop inactive profiler"); + Msg("[P] Tried to stop inactive profiler"); return; } if (m_profiler_type == CScriptProfilerType::None) { - Msg("Tried to stop none profiler type"); + Msg("[P] Tried to stop none type profiler"); return; } switch (m_profiler_type) { case CScriptProfilerType::Hook: - Msg("Stopping lua scripts hook profiler"); + Msg("[P] Stopping scripts hook profiler"); // Do not detach hook here, adding it means that it is already test run in the first place. break; - case CScriptProfilerType::Jit: + case CScriptProfilerType::Sampling: { - Msg("Stopping lua scripts jit profiler"); + Msg("[P] Stopping scripts sampling profiler"); + + luaJitProfilerStop(lua()); break; } @@ -106,9 +122,10 @@ void CScriptProfiler::stop() void CScriptProfiler::reset() { - Msg("Reset profiler"); + Msg("[P] Reset profiler"); m_profiling_portions.clear(); + m_profiling_log.clear(); } void CScriptProfiler::logReport() @@ -117,10 +134,10 @@ void CScriptProfiler::logReport() { case CScriptProfilerType::Hook: return logHookReport(); - case CScriptProfilerType::Jit: - return logJitReport(); + case CScriptProfilerType::Sampling: + return logSamplingReport(); default: - Msg("Nothing to report for profiler"); + Msg("[P] No active profiling data to report"); return; } } @@ -129,7 +146,7 @@ void CScriptProfiler::logHookReport() { if (m_profiling_portions.empty()) { - Msg("Nothing to report for hook profiler, data is missing"); + Msg("[P] Nothing to report for hook profiler, data is missing"); return; } @@ -147,11 +164,11 @@ void CScriptProfiler::logHookReport() total_duration += it->second.duration(); } - Msg("=================================================================="); - Msg("= Log hook profiler report, %d entries", entries.size()); - Msg("=================================================================="); - Msg("= By calls duration:"); - Msg("===="); + Msg("[P] =================================================================="); + Msg("[P] = Hook profiler report, %d entries", entries.size()); + Msg("[P] =================================================================="); + Msg("[P] = By calls duration:"); + Msg("[P] ===="); u64 index = 0; string512 buffer; @@ -164,7 +181,7 @@ void CScriptProfiler::logHookReport() if (index >= CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT) break; - Msg("[%3d] %6.3f ms (%5.2f%%) %6d calls, %6.3f ms avg : %s", index, (*it)->second.duration() / 1000.0, + Msg("[P] [%3d] %6.3f ms (%5.2f%%) %6d calls, %6.3f ms avg : %s", index, (*it)->second.duration() / 1000.0, ((f64)(*it)->second.duration() * 100.0) / (f64)total_duration, (*it)->second.count(), (f64)(*it)->second.duration() / (f64)(*it)->second.count() / 1000.0, (*it)->first.c_str()); @@ -172,9 +189,9 @@ void CScriptProfiler::logHookReport() index += 1; } - Msg("=================================================================="); - Msg("= By calls count:"); - Msg("===="); + Msg("[P] =================================================================="); + Msg("[P] = By calls count:"); + Msg("[P] ===="); index = 0; @@ -186,16 +203,16 @@ void CScriptProfiler::logHookReport() if (index >= CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT) break; - Msg("[%3d] %6d (%5.2f%%) : %s", index, (*it)->second.count(), + Msg("[P] [%3d] %6d (%5.2f%%) : %s", index, (*it)->second.count(), ((f64)(*it)->second.count() * 100.0) / (f64)total_count, (*it)->first.c_str()); index += 1; } - Msg("=================================================================="); - Msg("= Total function calls count: %d", total_count); - Msg("= Total function calls duration: %f ms", (f32) total_duration / 1000.0); - Msg("=================================================================="); + Msg("[P] =================================================================="); + Msg("[P] = Total function calls count: %d", total_count); + Msg("[P] = Total function calls duration: %f ms", (f32) total_duration / 1000.0); + Msg("[P] =================================================================="); FlushLog(); @@ -204,51 +221,120 @@ void CScriptProfiler::logHookReport() // todo; } -void CScriptProfiler::logJitReport() +void CScriptProfiler::logSamplingReport() { - // todo; - // todo; - // todo; + // todo: Separete save method, implement printing function here. + // todo: Separete save method, implement printing function here. + // todo: Separete save method, implement printing function here. + + if (m_profiling_log.empty()) + { + Msg("[P] Nothing to report for sampling profiler, data is missing"); + return; + } + + string_path log_file_name; + strconcat(sizeof(log_file_name), log_file_name, Core.ApplicationName, "_", Core.UserName, "_sampling_profile.perf"); + FS.update_path(log_file_name, "$logs$", log_file_name); + + Msg("[P] Saving sampling report to %s", log_file_name); + + IWriter* F = FS.w_open(log_file_name); + + if (F) + { + for (auto &it : m_profiling_log) + { + F->w_string(*it); + } + + FS.w_close(F); + } } void CScriptProfiler::saveReport() { - Log("Save profiler report"); + Log("[P] Saving profiler report"); // todo; // todo; // todo; } -void CScriptProfiler::attachLuaHook() +/* +* @returns whether profiling lua hook was/is attached to current VM context +*/ +bool CScriptProfiler::attachLuaHook() { - lua_State* L = lua(); - lua_Hook hook = lua_gethook(L); + lua_Hook hook = lua_gethook(lua()); - if (hook) + return hook ? hook == CScriptEngine::lua_hook_call : lua_sethook(lua(), CScriptEngine::lua_hook_call, LUA_MASKLINE | LUA_MASKCALL | LUA_MASKRET, 0); +} + +void CScriptProfiler::onDispose(lua_State* L) +{ + // When handling instance disposal (reinit), stop profiling for VM. + // Otherwise you cannot stop profiling because VM pointer will be destroyed and become inaccessible. + if (m_active && m_profiler_type == CScriptProfilerType::Sampling) { - if (hook != CScriptEngine::lua_hook_call) + Msg("[P] Disposing sampling dependencies"); + luaJitProfilerStop(L); + } +} + +void CScriptProfiler::onReinit(lua_State* L) +{ + // todo: Should we get old ref and detach profiler / hook? + // todo: Should we get old ref and detach profiler / hook? + // todo: Should we get old ref and detach profiler / hook? + + if (!m_active) + return; + + Msg("[P] Profiler reinit %d", lua()); + + switch (m_profiler_type) + { + case CScriptProfilerType::Hook: + if (!attachLuaHook()) { - Msg("Warning: hook already defined by something else, cannot take ownership as CScriptEngine"); + Msg("[P] Cannot start scripts hook profiler on reinit, hook was not set properly"); + return; } - } - else + + Msg("[P] Reinit scripts hook profiler"); + + m_profiling_portions.clear(); + + return; + case CScriptProfilerType::Sampling: { - Msg("Attaching lua scripts hook"); - lua_sethook(L, CScriptEngine::lua_hook_call, LUA_MASKLINE | LUA_MASKCALL | LUA_MASKRET, 0); + if (!luaIsJitProfilerDefined(lua())) + { + Msg("[P] Cannot start scripts sampling profiler on reinit, jit.profiler module is not defined"); + return; + } + + Msg("[P] Re-init scripts sampling profiler, attach handler"); + luaJitSamplingProfilerAttach(this); + + return; + } + + default: NODEFAULT; } } void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) { - if (!m_active || dbg->event == LUA_HOOKLINE) + if (!m_active || m_profiler_type != CScriptProfilerType::Hook || dbg->event == LUA_HOOKLINE) return; lua_Debug parent_stack_info; lua_Debug stack_info; // Check higher level of stack. - if (m_profile_level > 0) + if (m_hook_profile_level > 0) { if (!lua_getstack(L, 1, &parent_stack_info)) { @@ -268,7 +354,7 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) string512 buffer; auto name = stack_info.name ? stack_info.name : "?"; - auto parent_name = m_profile_level > 0 && parent_stack_info.name ? parent_stack_info.name : "?"; + auto parent_name = m_hook_profile_level > 0 && parent_stack_info.name ? parent_stack_info.name : "?"; auto short_src = stack_info.short_src; auto line_defined = stack_info.linedefined; @@ -276,7 +362,7 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) name = "lua-script-body"; // Include date from higher stack levels. - if (m_profile_level > 0) + if (m_hook_profile_level > 0) xr_sprintf(buffer, "%s [%d] - %s @ %s", name, line_defined, parent_name, short_src); else xr_sprintf(buffer, "%s [%d] @ %s", name, line_defined, parent_name, short_src); @@ -330,11 +416,108 @@ lua_State* CScriptProfiler::lua() const return this->m_engine->lua(); } +/* + * @returns used memory by lua state in bytes + */ +int CScriptProfiler::luaMemoryUsed(lua_State* L) +{ + return lua_gc(L, LUA_GCCOUNT, 0) * 1024 + lua_gc(L, LUA_GCCOUNTB, 0); +} + +/* + * @returns whether jit.profile module is defined in lua state + */ bool CScriptProfiler::luaIsJitProfilerDefined(lua_State* L) { - return true; + if (L == nullptr) + { + return false; + } + + auto top = lua_gettop(L); + + lua_getglobal(L, "require"); + lua_pushstring(L, "jit.profile"); + + if (lua_pcall(L, 1, 0, 0) == LUA_OK) + { + R_ASSERT2(top == lua_gettop(L), "Lua VM stack should not be affected by jit.profile check"); + return true; + } + else + { + // Remove error message to keep stack in previous state. + lua_pop(L, 1); + + R_ASSERT2(top == lua_gettop(L), "Lua VM stack should not be affected by jit.profile check"); + return true; + } +} + +/** +* Attach sampling profiling hooks. +* With provided period report samples and store information in profiler for further reporting. +*/ +void CScriptProfiler::luaJitSamplingProfilerAttach(CScriptProfiler* profiler) +{ + luaJitProfilerStart( + profiler->lua(), "fli", + [](void* data, lua_State* L, int samples, int vmstate) { + CScriptProfiler* profiler = static_cast(data); + string2048 buffer; + + // Build flamechart folded stack including frames and samples count + // Example: `C;frame_1_func:24;frame_2_func:45 4` + auto [dump, length] = luaJitProfilerDump(L, "flZ;", -64); + + buffer[0] = vmstate; + buffer[1] = ';'; + strncpy_s(buffer + 2, sizeof(buffer) - 2, dump, length); + buffer[length + 2] = ' '; + xr_itoa(samples, buffer + length + 3, 10); + + profiler->m_profiling_log.push_back(shared_str(buffer)); + }, + profiler); } -// todo: Add util to get frame info -// todo: Add util to get frame info -// todo: Add util to get frame info +/* + * Possible modes for profiling: + * f — profile with precision down to the function level + * l — profile with precision down to the line level + * i — sampling interval in milliseconds (default 10ms) + * + * Note: The actual sampling precision is OS-dependent. + * + * @param mode - jit profiling mode variant + * @returns whether jit profiler start call was successful + */ +void CScriptProfiler::luaJitProfilerStart(lua_State* L, cpcstr mode, luaJIT_profile_callback callback, void* data) +{ + // Only single JIT profiler can exist and it will not attach with multiple states. + // Also only VM started profiler can end it, be careful. + + luaJIT_profile_start(L, mode, callback, data); +} + +void CScriptProfiler::luaJitProfilerStop(lua_State* L) +{ + luaJIT_profile_stop(L); +} + +/* + * Possible format values for dump: + * f — dump function name + * F — dump function name, module:name for F variant + * p — preserve full path + * l — dump module:line + * Z — zap trailing separator + * i — Sampling interval in milliseconds (default 10ms) + */ +std::pair CScriptProfiler::luaJitProfilerDump(lua_State* L, cpcstr format, int depth) +{ + size_t length; + cpcstr dump = luaJIT_profile_dumpstack(L, format, depth, &length); + + return std::make_pair(dump, length); +} diff --git a/src/xrScriptEngine/script_profiler.hpp b/src/xrScriptEngine/script_profiler.hpp index 29a17cd224c..e477b8aff34 100644 --- a/src/xrScriptEngine/script_profiler.hpp +++ b/src/xrScriptEngine/script_profiler.hpp @@ -66,7 +66,7 @@ enum class CScriptProfilerType : u32 { None = 0, Hook = 1, - Jit = 2, + Sampling = 2, }; class XRSCRIPTENGINE_API CScriptProfiler @@ -82,11 +82,18 @@ class XRSCRIPTENGINE_API CScriptProfiler bool m_active; + // todo: Add period parameter for sampling profiler. + // Profiling level - number of stacks to check before each function call. // Helps validating results of same functions called from different places vs totals by specific function. - u8 m_profile_level; + // todo: Handle level / provide level properly. + u8 m_hook_profile_level; CScriptProfilerType m_profiler_type; + // todo: Profiler-type specific naming for containers. + // todo: Profiler-type specific naming for containers. + // todo: Profiler-type specific naming for containers. xr_unordered_map m_profiling_portions; + xr_vector m_profiling_log; public: CScriptProfiler(CScriptEngine* engine); @@ -94,20 +101,29 @@ class XRSCRIPTENGINE_API CScriptProfiler bool isActive() const { return m_active; }; - void start(CScriptProfilerType profiler_type = CScriptProfilerType::Hook); + void start(CScriptProfilerType profiler_type = CScriptProfilerType::Hook); void stop(); void reset(); void logReport(); void logHookReport(); - void logJitReport(); + void logSamplingReport(); void saveReport(); + // todo: Save sampling report. + // todo: Save hook. - void attachLuaHook(); + bool attachLuaHook(); + void onReinit(lua_State* L); + void onDispose(lua_State* L); void onLuaHookCall(lua_State* L, lua_Debug* dbg); private: lua_State* lua() const; + static int luaMemoryUsed(lua_State* L); static bool luaIsJitProfilerDefined(lua_State* L); + static void luaJitSamplingProfilerAttach(CScriptProfiler* profiler); + static void luaJitProfilerStart(lua_State* L, cpcstr mode, luaJIT_profile_callback callback, void* data); + static void luaJitProfilerStop(lua_State* L); + static std::pair luaJitProfilerDump(lua_State* L, cpcstr format, int depth); }; diff --git a/src/xrScriptEngine/xrScriptEngine.hpp b/src/xrScriptEngine/xrScriptEngine.hpp index a1bdf1f5ee3..fc16f5fcb55 100644 --- a/src/xrScriptEngine/xrScriptEngine.hpp +++ b/src/xrScriptEngine/xrScriptEngine.hpp @@ -10,6 +10,7 @@ extern "C" { #include #include #include +#include } #pragma warning(disable : 4127) // conditional expression is constant From f1ebac885b10268e5951d8e213854fa68cd1921c Mon Sep 17 00:00:00 2001 From: Neloreck Date: Fri, 17 Jan 2025 01:55:30 +0200 Subject: [PATCH 06/24] Do not initialize profiler in editor mode. Use profiling type specific naming for class members. --- src/xrScriptEngine/script_engine.cpp | 2 +- src/xrScriptEngine/script_profiler.cpp | 30 +++++++++++++------------- src/xrScriptEngine/script_profiler.hpp | 8 +++---- 3 files changed, 20 insertions(+), 20 deletions(-) diff --git a/src/xrScriptEngine/script_engine.cpp b/src/xrScriptEngine/script_engine.cpp index d0add0eff3a..1e1571654a5 100644 --- a/src/xrScriptEngine/script_engine.cpp +++ b/src/xrScriptEngine/script_engine.cpp @@ -764,7 +764,7 @@ CScriptEngine::CScriptEngine(bool is_editor, bool is_with_profiler) m_current_thread = nullptr; m_stack_is_ready = false; m_virtual_machine = nullptr; - m_profiler = is_with_profiler ? xr_new(this) : nullptr; + m_profiler = is_with_profiler && !is_editor ? xr_new(this) : nullptr; m_stack_level = 0; m_reload_modules = false; m_last_no_file_length = 0; diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index 23ae4f29557..6dbe7fd9459 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -57,7 +57,7 @@ void CScriptProfiler::start(CScriptProfilerType profiler_type) Msg("[P] Starting scripts hook profiler"); - m_profiling_portions.clear(); + m_hook_profiling_portions.clear(); m_profiler_type = profiler_type; m_active = true; @@ -124,8 +124,8 @@ void CScriptProfiler::reset() { Msg("[P] Reset profiler"); - m_profiling_portions.clear(); - m_profiling_log.clear(); + m_hook_profiling_portions.clear(); + m_sampling_profiling_log.clear(); } void CScriptProfiler::logReport() @@ -144,7 +144,7 @@ void CScriptProfiler::logReport() void CScriptProfiler::logHookReport() { - if (m_profiling_portions.empty()) + if (m_hook_profiling_portions.empty()) { Msg("[P] Nothing to report for hook profiler, data is missing"); return; @@ -153,10 +153,10 @@ void CScriptProfiler::logHookReport() u64 total_count = 0; u64 total_duration = 0; - xr_vector entries; - entries.reserve(m_profiling_portions.size()); + xr_vector entries; + entries.reserve(m_hook_profiling_portions.size()); - for (auto it = m_profiling_portions.begin(); it != m_profiling_portions.end(); it++) + for (auto it = m_hook_profiling_portions.begin(); it != m_hook_profiling_portions.end(); it++) { entries.push_back(it); @@ -227,7 +227,7 @@ void CScriptProfiler::logSamplingReport() // todo: Separete save method, implement printing function here. // todo: Separete save method, implement printing function here. - if (m_profiling_log.empty()) + if (m_sampling_profiling_log.empty()) { Msg("[P] Nothing to report for sampling profiler, data is missing"); return; @@ -243,7 +243,7 @@ void CScriptProfiler::logSamplingReport() if (F) { - for (auto &it : m_profiling_log) + for (auto &it : m_sampling_profiling_log) { F->w_string(*it); } @@ -304,7 +304,7 @@ void CScriptProfiler::onReinit(lua_State* L) Msg("[P] Reinit scripts hook profiler"); - m_profiling_portions.clear(); + m_hook_profiling_portions.clear(); return; case CScriptProfilerType::Sampling: @@ -367,8 +367,8 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) else xr_sprintf(buffer, "%s [%d] @ %s", name, line_defined, parent_name, short_src); - auto it = m_profiling_portions.find(buffer); - bool exists = it != m_profiling_portions.end(); + auto it = m_hook_profiling_portions.find(buffer); + bool exists = it != m_hook_profiling_portions.end(); switch (dbg->event) { @@ -380,11 +380,11 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) } else { - CScriptProfilerPortion portion; + CScriptProfilerHookPortion portion; portion.start(); - m_profiling_portions.emplace(buffer, std::move(portion)); + m_hook_profiling_portions.emplace(buffer, std::move(portion)); } return; @@ -476,7 +476,7 @@ void CScriptProfiler::luaJitSamplingProfilerAttach(CScriptProfiler* profiler) buffer[length + 2] = ' '; xr_itoa(samples, buffer + length + 3, 10); - profiler->m_profiling_log.push_back(shared_str(buffer)); + profiler->m_sampling_profiling_log.push_back(shared_str(buffer)); }, profiler); } diff --git a/src/xrScriptEngine/script_profiler.hpp b/src/xrScriptEngine/script_profiler.hpp index e477b8aff34..8b31052ab2c 100644 --- a/src/xrScriptEngine/script_profiler.hpp +++ b/src/xrScriptEngine/script_profiler.hpp @@ -6,7 +6,7 @@ struct lua_State; struct lua_Debug; -class CScriptProfilerPortion { +class CScriptProfilerHookPortion { using Clock = std::chrono::high_resolution_clock; using Time = Clock::time_point; using Duration = Clock::duration; @@ -19,7 +19,7 @@ class CScriptProfilerPortion { Duration m_duration; public: - CScriptProfilerPortion(): m_calls_count(0), m_calls_active(0), m_duration(0), m_started_at() {} + CScriptProfilerHookPortion(): m_calls_count(0), m_calls_active(0), m_duration(0), m_started_at() {} void start() { @@ -92,8 +92,8 @@ class XRSCRIPTENGINE_API CScriptProfiler // todo: Profiler-type specific naming for containers. // todo: Profiler-type specific naming for containers. // todo: Profiler-type specific naming for containers. - xr_unordered_map m_profiling_portions; - xr_vector m_profiling_log; + xr_unordered_map m_hook_profiling_portions; + xr_vector m_sampling_profiling_log; public: CScriptProfiler(CScriptEngine* engine); From 6c24633603d50a71b19d1e67758fad974b5b3123 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Fri, 17 Jan 2025 03:14:31 +0200 Subject: [PATCH 07/24] Const expressions for args. Use interval param in sampling profiler. --- src/xrScriptEngine/script_profiler.cpp | 82 +++++++++++++++++++++----- src/xrScriptEngine/script_profiler.hpp | 38 +++++++----- 2 files changed, 89 insertions(+), 31 deletions(-) diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index 6dbe7fd9459..55741ad26b3 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -9,18 +9,22 @@ CScriptProfiler::CScriptProfiler(CScriptEngine* engine) m_engine = engine; m_active = false; - m_hook_profile_level = 1; m_profiler_type = CScriptProfilerType::None; + m_sampling_profile_interval = PROFILE_SAMPLING_INTERVAL_DEFAULT; + m_hook_profile_level = PROFILE_HOOK_LEVEL_DEFAULT; - if (strstr(Core.Params, "-lua_profiler")) + if (strstr(Core.Params, ARGUMENT_PROFILER_DEFAULT)) start(); - else if (strstr(Core.Params, "-lua_hook_profiler")) + else if (strstr(Core.Params, ARGUMENT_PROFILER_HOOK)) start(CScriptProfilerType::Hook); - else if (strstr(Core.Params, "-lua_sampling_profiler")) + else if (strstr(Core.Params, ARGUMENT_PROFILER_SAMPLING)) start(CScriptProfilerType::Sampling); } -CScriptProfiler::~CScriptProfiler() {} +CScriptProfiler::~CScriptProfiler() +{ + m_engine = nullptr; +} void CScriptProfiler::start(CScriptProfilerType profiler_type) { @@ -70,8 +74,8 @@ void CScriptProfiler::start(CScriptProfilerType profiler_type) return; } - Msg("[P] Starting scripts sampling profiler"); - luaJitSamplingProfilerAttach(this); + Msg("[P] Starting scripts sampling profiler, interval: %d", m_sampling_profile_interval); + luaJitSamplingProfilerAttach(this, m_sampling_profile_interval); m_profiler_type = profiler_type; m_active = true; @@ -254,13 +258,60 @@ void CScriptProfiler::logSamplingReport() void CScriptProfiler::saveReport() { - Log("[P] Saving profiler report"); + switch (m_profiler_type) + { + case CScriptProfilerType::Hook: + return saveHookReport(); + case CScriptProfilerType::Sampling: + return saveSamplingReport(); + default: + Msg("[P] No active profiling data to save report"); + return; + } +} + +void CScriptProfiler::saveHookReport() +{ + if (m_hook_profiling_portions.empty()) + { + Msg("[P] Nothing to report for hook profiler, data is missing"); + return; + } + + Log("[P] Saving hook profiler report"); // todo; // todo; // todo; } +void CScriptProfiler::saveSamplingReport() +{ + if (m_sampling_profiling_log.empty()) + { + Msg("[P] Nothing to report for sampling profiler, data is missing"); + return; + } + + string_path log_file_name; + strconcat(sizeof(log_file_name), log_file_name, Core.ApplicationName, "_", Core.UserName, "_sampling_profile.perf"); + FS.update_path(log_file_name, "$logs$", log_file_name); + + Msg("[P] Saving sampling report to %s", log_file_name); + + IWriter* F = FS.w_open(log_file_name); + + if (F) + { + for (auto &it : m_sampling_profiling_log) + { + F->w_string(*it); + } + + FS.w_close(F); + } +} + /* * @returns whether profiling lua hook was/is attached to current VM context */ @@ -284,10 +335,6 @@ void CScriptProfiler::onDispose(lua_State* L) void CScriptProfiler::onReinit(lua_State* L) { - // todo: Should we get old ref and detach profiler / hook? - // todo: Should we get old ref and detach profiler / hook? - // todo: Should we get old ref and detach profiler / hook? - if (!m_active) return; @@ -315,13 +362,13 @@ void CScriptProfiler::onReinit(lua_State* L) return; } - Msg("[P] Re-init scripts sampling profiler, attach handler"); - luaJitSamplingProfilerAttach(this); + Msg("[P] Re-init scripts sampling profiler - attach handler, interval: %d", m_sampling_profile_interval); + luaJitSamplingProfilerAttach(this, m_sampling_profile_interval); return; } - default: NODEFAULT; + default: NODEFAULT; } } @@ -458,8 +505,11 @@ bool CScriptProfiler::luaIsJitProfilerDefined(lua_State* L) * Attach sampling profiling hooks. * With provided period report samples and store information in profiler for further reporting. */ -void CScriptProfiler::luaJitSamplingProfilerAttach(CScriptProfiler* profiler) +void CScriptProfiler::luaJitSamplingProfilerAttach(CScriptProfiler* profiler, u32 interval) { + string32 buffer = "fli"; + xr_itoa(interval, buffer + 3, 10); + luaJitProfilerStart( profiler->lua(), "fli", [](void* data, lua_State* L, int samples, int vmstate) { diff --git a/src/xrScriptEngine/script_profiler.hpp b/src/xrScriptEngine/script_profiler.hpp index 8b31052ab2c..45dc5552e43 100644 --- a/src/xrScriptEngine/script_profiler.hpp +++ b/src/xrScriptEngine/script_profiler.hpp @@ -76,22 +76,30 @@ class XRSCRIPTENGINE_API CScriptProfiler using Duration = Clock::duration; private: + constexpr static cpcstr ARGUMENT_PROFILER_DEFAULT = "-lua_profiler"; + constexpr static cpcstr ARGUMENT_PROFILER_HOOK = "-lua_hook_profiler"; + constexpr static cpcstr ARGUMENT_PROFILER_SAMPLING = "-lua_sampling_profiler"; + static const u32 PROFILE_ENTRIES_LOG_LIMIT = 128; + static const u32 PROFILE_HOOK_LEVEL_DEFAULT = 1; + static const u32 PROFILE_SAMPLING_INTERVAL_DEFAULT = 10; + static const u32 PROFILE_SAMPLING_INTERVAL_MAX = 1000; CScriptEngine* m_engine; bool m_active; - - // todo: Add period parameter for sampling profiler. - - // Profiling level - number of stacks to check before each function call. - // Helps validating results of same functions called from different places vs totals by specific function. - // todo: Handle level / provide level properly. - u8 m_hook_profile_level; CScriptProfilerType m_profiler_type; - // todo: Profiler-type specific naming for containers. - // todo: Profiler-type specific naming for containers. - // todo: Profiler-type specific naming for containers. + + /* + * Profiling level - number of stacks to check before each function call. + * Helps validating results of same functions called from different places vs totals by specific function. + */ + u32 m_hook_profile_level; + /* + * Sampling interval for JIT based profiler. + * Value should be set in ms and defaults to 10ms. + */ + u32 m_sampling_profile_interval; xr_unordered_map m_hook_profiling_portions; xr_vector m_sampling_profiling_log; @@ -109,20 +117,20 @@ class XRSCRIPTENGINE_API CScriptProfiler void logHookReport(); void logSamplingReport(); void saveReport(); - // todo: Save sampling report. - // todo: Save hook. + void saveHookReport(); + void saveSamplingReport(); - bool attachLuaHook(); void onReinit(lua_State* L); void onDispose(lua_State* L); void onLuaHookCall(lua_State* L, lua_Debug* dbg); private: lua_State* lua() const; + bool attachLuaHook(); - static int luaMemoryUsed(lua_State* L); + static int luaMemoryUsed(lua_State* L); static bool luaIsJitProfilerDefined(lua_State* L); - static void luaJitSamplingProfilerAttach(CScriptProfiler* profiler); + static void luaJitSamplingProfilerAttach(CScriptProfiler* profiler, u32 interval); static void luaJitProfilerStart(lua_State* L, cpcstr mode, luaJIT_profile_callback callback, void* data); static void luaJitProfilerStop(lua_State* L); static std::pair luaJitProfilerDump(lua_State* L, cpcstr format, int depth); From 40e96c1c8d3e5a351b5f1653e658d492e178157f Mon Sep 17 00:00:00 2001 From: Neloreck Date: Fri, 17 Jan 2025 03:45:52 +0200 Subject: [PATCH 08/24] Separate hook start methods, simple generic start with defaults. Declare separate start methods in script export. --- src/xrScriptEngine/ScriptEngineScript.cpp | 8 ++ src/xrScriptEngine/script_profiler.cpp | 99 ++++++++++++++--------- src/xrScriptEngine/script_profiler.hpp | 13 +-- 3 files changed, 79 insertions(+), 41 deletions(-) diff --git a/src/xrScriptEngine/ScriptEngineScript.cpp b/src/xrScriptEngine/ScriptEngineScript.cpp index 4bf842b62a7..927e212cc92 100644 --- a/src/xrScriptEngine/ScriptEngineScript.cpp +++ b/src/xrScriptEngine/ScriptEngineScript.cpp @@ -183,6 +183,14 @@ SCRIPT_EXPORT(CScriptEngine, (), { GEnv.ScriptEngine->m_profiler->start(hook_type); }), + def("start_sampling_mode", +[](u32 sampling_interval) + { + GEnv.ScriptEngine->m_profiler->startSamplingMode(sampling_interval); + }), + def("start_hook_mode", +[](u32 stack_depth) + { + GEnv.ScriptEngine->m_profiler->startHookMode(stack_depth); + }), def("stop", +[]() { GEnv.ScriptEngine->m_profiler->stop(); diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index 55741ad26b3..b7689a17b5a 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -7,11 +7,10 @@ CScriptProfiler::CScriptProfiler(CScriptEngine* engine) R_ASSERT(engine != NULL); m_engine = engine; - m_active = false; m_profiler_type = CScriptProfilerType::None; m_sampling_profile_interval = PROFILE_SAMPLING_INTERVAL_DEFAULT; - m_hook_profile_level = PROFILE_HOOK_LEVEL_DEFAULT; + m_hook_profile_depth = PROFILE_HOOK_DEPTH_DEFAULT; if (strstr(Core.Params, ARGUMENT_PROFILER_DEFAULT)) start(); @@ -28,63 +27,88 @@ CScriptProfiler::~CScriptProfiler() void CScriptProfiler::start(CScriptProfilerType profiler_type) { - if (m_active) + switch (profiler_type) { - Msg("[P] Tried to start already active profiler, operation ignored"); - return; + case CScriptProfilerType::Hook: + startHookMode(PROFILE_HOOK_DEPTH_DEFAULT); + return; + case CScriptProfilerType::Sampling: + startSamplingMode(PROFILE_SAMPLING_INTERVAL_DEFAULT); + return; + case CScriptProfilerType::None: + Msg("[P] Tried to start none type profiler"); + return; + default: NODEFAULT; } +} - if (profiler_type == CScriptProfilerType::None) +void CScriptProfiler::startHookMode(u32 stack_depth) +{ + if (m_active) { - Msg("[P] Tried to start none type profiler"); + Msg("[P] Tried to start already active profiler, operation ignored"); return; } if (!lua()) { - Msg("[P] Activating profiler on lua engine start, waiting init"); + Msg("[P] Activating hook profiler on lua engine start, waiting init"); - m_profiler_type = profiler_type; + m_profiler_type = CScriptProfilerType::Hook; m_active = true; return; } - switch (profiler_type) + clamp(stack_depth, 0u, PROFILE_SAMPLING_INTERVAL_MAX); + + if (!attachLuaHook()) { - case CScriptProfilerType::Hook: - if (!attachLuaHook()) - { - Msg("[P] Cannot start scripts hook profiler, hook was not set properly"); - return; - } + Msg("[P] Cannot start scripts hook profiler, hook was not set properly"); + return; + } - Msg("[P] Starting scripts hook profiler"); + Msg("[P] Starting scripts hook profiler, depth: %d", stack_depth); - m_hook_profiling_portions.clear(); - m_profiler_type = profiler_type; - m_active = true; + m_hook_profile_depth = stack_depth; + m_hook_profiling_portions.clear(); + m_profiler_type = CScriptProfilerType::Hook; + m_active = true; +} - return; - case CScriptProfilerType::Sampling: +void CScriptProfiler::startSamplingMode(u32 sampling_interval) +{ + if (m_active) { - if (!luaIsJitProfilerDefined(lua())) - { - Msg("[P] Cannot start scripts sampling profiler, jit.profiler module is not defined"); - return; - } + Msg("[P] Tried to start already active profiler, operation ignored"); + return; + } - Msg("[P] Starting scripts sampling profiler, interval: %d", m_sampling_profile_interval); - luaJitSamplingProfilerAttach(this, m_sampling_profile_interval); + if (!lua()) + { + Msg("[P] Activating sampling profiler on lua engine start, waiting init"); - m_profiler_type = profiler_type; + m_profiler_type = CScriptProfilerType::Sampling; m_active = true; - return; + return; } - default: NODEFAULT; + if (!luaIsJitProfilerDefined(lua())) + { + Msg("[P] Cannot start scripts sampling profiler, jit.profiler module is not defined"); + return; } + + clamp(sampling_interval, 1u, PROFILE_SAMPLING_INTERVAL_MAX); + + Msg("[P] Starting scripts sampling profiler, interval: %d", sampling_interval); + + luaJitSamplingProfilerAttach(this, sampling_interval); + + m_sampling_profile_interval = sampling_interval; + m_profiler_type = CScriptProfilerType::Sampling; + m_active = true; } void CScriptProfiler::stop() @@ -380,8 +404,11 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) lua_Debug parent_stack_info; lua_Debug stack_info; + // todo: Implement dynamic depth. + // todo: Implement dynamic depth. + // Check higher level of stack. - if (m_hook_profile_level > 0) + if (m_hook_profile_depth > 0) { if (!lua_getstack(L, 1, &parent_stack_info)) { @@ -401,7 +428,7 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) string512 buffer; auto name = stack_info.name ? stack_info.name : "?"; - auto parent_name = m_hook_profile_level > 0 && parent_stack_info.name ? parent_stack_info.name : "?"; + auto parent_name = m_hook_profile_depth > 0 && parent_stack_info.name ? parent_stack_info.name : "?"; auto short_src = stack_info.short_src; auto line_defined = stack_info.linedefined; @@ -409,7 +436,7 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) name = "lua-script-body"; // Include date from higher stack levels. - if (m_hook_profile_level > 0) + if (m_hook_profile_depth > 0) xr_sprintf(buffer, "%s [%d] - %s @ %s", name, line_defined, parent_name, short_src); else xr_sprintf(buffer, "%s [%d] @ %s", name, line_defined, parent_name, short_src); @@ -511,7 +538,7 @@ void CScriptProfiler::luaJitSamplingProfilerAttach(CScriptProfiler* profiler, u3 xr_itoa(interval, buffer + 3, 10); luaJitProfilerStart( - profiler->lua(), "fli", + profiler->lua(), buffer, [](void* data, lua_State* L, int samples, int vmstate) { CScriptProfiler* profiler = static_cast(data); string2048 buffer; diff --git a/src/xrScriptEngine/script_profiler.hpp b/src/xrScriptEngine/script_profiler.hpp index 45dc5552e43..d58be66370a 100644 --- a/src/xrScriptEngine/script_profiler.hpp +++ b/src/xrScriptEngine/script_profiler.hpp @@ -76,25 +76,26 @@ class XRSCRIPTENGINE_API CScriptProfiler using Duration = Clock::duration; private: + // List of commnad line args for startup profuler attach: constexpr static cpcstr ARGUMENT_PROFILER_DEFAULT = "-lua_profiler"; constexpr static cpcstr ARGUMENT_PROFILER_HOOK = "-lua_hook_profiler"; constexpr static cpcstr ARGUMENT_PROFILER_SAMPLING = "-lua_sampling_profiler"; static const u32 PROFILE_ENTRIES_LOG_LIMIT = 128; - static const u32 PROFILE_HOOK_LEVEL_DEFAULT = 1; + static const u32 PROFILE_HOOK_DEPTH_DEFAULT = 1; + static const u32 PROFILE_HOOK_DEPTH_MAX = 1; static const u32 PROFILE_SAMPLING_INTERVAL_DEFAULT = 10; static const u32 PROFILE_SAMPLING_INTERVAL_MAX = 1000; CScriptEngine* m_engine; - - bool m_active; CScriptProfilerType m_profiler_type; + bool m_active; /* - * Profiling level - number of stacks to check before each function call. + * Profiling depth - number of stacks to summarise function call trace. * Helps validating results of same functions called from different places vs totals by specific function. */ - u32 m_hook_profile_level; + u32 m_hook_profile_depth; /* * Sampling interval for JIT based profiler. * Value should be set in ms and defaults to 10ms. @@ -110,6 +111,8 @@ class XRSCRIPTENGINE_API CScriptProfiler bool isActive() const { return m_active; }; void start(CScriptProfilerType profiler_type = CScriptProfilerType::Hook); + void startSamplingMode(u32 sampling_interval); + void startHookMode(u32 stack_depth); void stop(); void reset(); From 6f8e6d4a60017ffc8dd2d007d2381354df86e48b Mon Sep 17 00:00:00 2001 From: Neloreck Date: Fri, 17 Jan 2025 04:27:08 +0200 Subject: [PATCH 09/24] Safer checking for luaIsJitProfilerDefined. --- src/xrScriptEngine/script_engine.cpp | 4 +++- src/xrScriptEngine/script_engine.hpp | 3 ++- src/xrScriptEngine/script_profiler.cpp | 31 +++++--------------------- src/xrScriptEngine/script_profiler.hpp | 1 + 4 files changed, 12 insertions(+), 27 deletions(-) diff --git a/src/xrScriptEngine/script_engine.cpp b/src/xrScriptEngine/script_engine.cpp index 1e1571654a5..24f81799706 100644 --- a/src/xrScriptEngine/script_engine.cpp +++ b/src/xrScriptEngine/script_engine.cpp @@ -1046,7 +1046,9 @@ void CScriptEngine::init(ExporterFunc exporterFunc, bool loadGlobalNamespace) // if (jit == nil) then // profiler.setup_hook() // end - if (!strstr(Core.Params, "-nojit")) + // + // Update: '-nojit' option adds garbage to stack and luabind calls fail + if (!strstr(Core.Params, ARGUMENT_ENGINE_NOJIT)) { luajit::open_lib(lua(), LUA_JITLIBNAME, luaopen_jit); // Xottab_DUTY: commented this. Let's use default opt level, which is 3 diff --git a/src/xrScriptEngine/script_engine.hpp b/src/xrScriptEngine/script_engine.hpp index 0fa4e87be8e..cd8a12fa86a 100644 --- a/src/xrScriptEngine/script_engine.hpp +++ b/src/xrScriptEngine/script_engine.hpp @@ -71,7 +71,8 @@ extern Flags32 XRSCRIPTENGINE_API g_LuaDebug; class XRSCRIPTENGINE_API CScriptEngine { public: - typedef AssociativeVector CScriptProcessStorage; + constexpr static cpcstr ARGUMENT_ENGINE_NOJIT = "-nojit"; + typedef AssociativeVector CScriptProcessStorage; static const char* const GlobalNamespace; private: diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index b7689a17b5a..ae05fefe244 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -96,7 +96,7 @@ void CScriptProfiler::startSamplingMode(u32 sampling_interval) if (!luaIsJitProfilerDefined(lua())) { - Msg("[P] Cannot start scripts sampling profiler, jit.profiler module is not defined"); + Msg("[P] Cannot start scripts sampling profiler, jit module is not defined"); return; } @@ -499,33 +499,14 @@ int CScriptProfiler::luaMemoryUsed(lua_State* L) } /* - * @returns whether jit.profile module is defined in lua state + * @returns whether jit is enabled */ bool CScriptProfiler::luaIsJitProfilerDefined(lua_State* L) { - if (L == nullptr) - { - return false; - } - - auto top = lua_gettop(L); - - lua_getglobal(L, "require"); - lua_pushstring(L, "jit.profile"); - - if (lua_pcall(L, 1, 0, 0) == LUA_OK) - { - R_ASSERT2(top == lua_gettop(L), "Lua VM stack should not be affected by jit.profile check"); - return true; - } - else - { - // Remove error message to keep stack in previous state. - lua_pop(L, 1); - - R_ASSERT2(top == lua_gettop(L), "Lua VM stack should not be affected by jit.profile check"); - return true; - } + // Safest and least invasive way to check it. + // Other methods affect lua stack and may add interfere with VS extensions / other hooks / error callbacks. + // We assume that we do not load JIT libs only if nojit parameter is provided. + return !strstr(Core.Params, CScriptEngine::ARGUMENT_ENGINE_NOJIT); } /** diff --git a/src/xrScriptEngine/script_profiler.hpp b/src/xrScriptEngine/script_profiler.hpp index d58be66370a..50e55140670 100644 --- a/src/xrScriptEngine/script_profiler.hpp +++ b/src/xrScriptEngine/script_profiler.hpp @@ -76,6 +76,7 @@ class XRSCRIPTENGINE_API CScriptProfiler using Duration = Clock::duration; private: + // todo: Can we make some global module to store all the arguments as experessions? // List of commnad line args for startup profuler attach: constexpr static cpcstr ARGUMENT_PROFILER_DEFAULT = "-lua_profiler"; constexpr static cpcstr ARGUMENT_PROFILER_HOOK = "-lua_hook_profiler"; From 3216e9feda7a3b45a57f60fa377389bf04a0c8d2 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Fri, 17 Jan 2025 04:52:03 +0200 Subject: [PATCH 10/24] Respect -nojit option on startup with profiling active. Corrected stop method. --- src/xrScriptEngine/script_profiler.cpp | 30 +++++++++++--------------- 1 file changed, 12 insertions(+), 18 deletions(-) diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index ae05fefe244..75cc34524b1 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -84,6 +84,12 @@ void CScriptProfiler::startSamplingMode(u32 sampling_interval) return; } + if (!luaIsJitProfilerDefined(lua())) + { + Msg("[P] Cannot start scripts sampling profiler, jit module is not defined"); + return; + } + if (!lua()) { Msg("[P] Activating sampling profiler on lua engine start, waiting init"); @@ -94,12 +100,6 @@ void CScriptProfiler::startSamplingMode(u32 sampling_interval) return; } - if (!luaIsJitProfilerDefined(lua())) - { - Msg("[P] Cannot start scripts sampling profiler, jit module is not defined"); - return; - } - clamp(sampling_interval, 1u, PROFILE_SAMPLING_INTERVAL_MAX); Msg("[P] Starting scripts sampling profiler, interval: %d", sampling_interval); @@ -119,33 +119,27 @@ void CScriptProfiler::stop() return; } - if (m_profiler_type == CScriptProfilerType::None) - { - Msg("[P] Tried to stop none type profiler"); - return; - } - switch (m_profiler_type) { case CScriptProfilerType::Hook: Msg("[P] Stopping scripts hook profiler"); - // Do not detach hook here, adding it means that it is already test run in the first place. - break; case CScriptProfilerType::Sampling: { Msg("[P] Stopping scripts sampling profiler"); - + // Detach profiler from luajit, stop operation will be ignore anyway if it is stopped/captured by another VM. luaJitProfilerStop(lua()); - break; } - - default: NODEFAULT; + default: + Msg("[P] Tried to stop none type profiler"); + return; } m_active = false; + m_hook_profiling_portions.clear(); + m_sampling_profiling_log.clear(); } void CScriptProfiler::reset() From 4ba2681f8275ca436fb449570ec5d8b0bad1cb23 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Fri, 17 Jan 2025 20:42:46 +0200 Subject: [PATCH 11/24] Separate portions file. Collect portions instead of full stack for sampling profiler. --- src/xrScriptEngine/CMakeLists.txt | 1 + src/xrScriptEngine/script_profiler.cpp | 46 +++++++--- src/xrScriptEngine/script_profiler.hpp | 66 +------------- .../script_profiler_portions.hpp | 85 +++++++++++++++++++ src/xrScriptEngine/xrScriptEngine.vcxproj | 1 + .../xrScriptEngine.vcxproj.filters | 3 + 6 files changed, 126 insertions(+), 76 deletions(-) create mode 100644 src/xrScriptEngine/script_profiler_portions.hpp diff --git a/src/xrScriptEngine/CMakeLists.txt b/src/xrScriptEngine/CMakeLists.txt index 5ce29f29e17..8383d9bfff7 100644 --- a/src/xrScriptEngine/CMakeLists.txt +++ b/src/xrScriptEngine/CMakeLists.txt @@ -16,6 +16,7 @@ target_sources_grouped( script_lua_helper.hpp script_profiler.cpp script_profiler.hpp + script_profiler_portions.hpp ) target_sources_grouped( diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index 75cc34524b1..28b88d22d21 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -267,7 +267,7 @@ void CScriptProfiler::logSamplingReport() { for (auto &it : m_sampling_profiling_log) { - F->w_string(*it); + F->w_string(*it.getFoldedStack()); } FS.w_close(F); @@ -323,7 +323,7 @@ void CScriptProfiler::saveSamplingReport() { for (auto &it : m_sampling_profiling_log) { - F->w_string(*it); + F->w_string(*it.getFoldedStack()); } FS.w_close(F); @@ -516,19 +516,14 @@ void CScriptProfiler::luaJitSamplingProfilerAttach(CScriptProfiler* profiler, u3 profiler->lua(), buffer, [](void* data, lua_State* L, int samples, int vmstate) { CScriptProfiler* profiler = static_cast(data); - string2048 buffer; - // Build flamechart folded stack including frames and samples count - // Example: `C;frame_1_func:24;frame_2_func:45 4` - auto [dump, length] = luaJitProfilerDump(L, "flZ;", -64); - - buffer[0] = vmstate; - buffer[1] = ';'; - strncpy_s(buffer + 2, sizeof(buffer) - 2, dump, length); - buffer[length + 2] = ' '; - xr_itoa(samples, buffer + length + 3, 10); - - profiler->m_sampling_profiling_log.push_back(shared_str(buffer)); + profiler->m_sampling_profiling_log.push_back(std::move(CScriptProfilerSamplingPortion( + luaJitProfilerDumpToString(L, "fl", 1), + luaJitProfilerDumpToString(L, "flZ;", -64), + samples, + vmstate, + luaMemoryUsed(L) + ))); }, profiler); } @@ -557,6 +552,29 @@ void CScriptProfiler::luaJitProfilerStop(lua_State* L) luaJIT_profile_stop(L); } +/* + * Possible format values for dump: + * f — dump function name + * F — dump function name, module:name for F variant + * p — preserve full path + * l — dump module:line + * Z — zap trailing separator + * i — Sampling interval in milliseconds (default 10ms) + */ +shared_str CScriptProfiler::luaJitProfilerDumpToString(lua_State* L, cpcstr format, int depth) +{ + string2048 buffer; + size_t length; + cpcstr dump = luaJIT_profile_dumpstack(L, format, depth, &length); + + R_ASSERT2(length < 2048, "Profiling dump buffer overflow"); + + strncpy_s(buffer, sizeof(buffer), dump, length); + buffer[length] = 0; + + return shared_str(buffer); +} + /* * Possible format values for dump: * f — dump function name diff --git a/src/xrScriptEngine/script_profiler.hpp b/src/xrScriptEngine/script_profiler.hpp index 50e55140670..43c8dcf9d71 100644 --- a/src/xrScriptEngine/script_profiler.hpp +++ b/src/xrScriptEngine/script_profiler.hpp @@ -1,67 +1,12 @@ #pragma once #include "pch.hpp" +#include "script_profiler_portions.hpp" #include "xrCommon/xr_unordered_map.h" struct lua_State; struct lua_Debug; -class CScriptProfilerHookPortion { - using Clock = std::chrono::high_resolution_clock; - using Time = Clock::time_point; - using Duration = Clock::duration; - - private: - u64 m_calls_count; - u32 m_calls_active; - - Time m_started_at; - Duration m_duration; - - public: - CScriptProfilerHookPortion(): m_calls_count(0), m_calls_active(0), m_duration(0), m_started_at() {} - - void start() - { - m_calls_count += 1; - - if (m_calls_active) - { - m_calls_active += 1; - return; - } - else - { - m_started_at = Clock::now(); - m_calls_active += 1; - } - } - - void stop() - { - if (!m_calls_active) - return; - - m_calls_active -= 1; - - if (m_calls_active) - return; - - const auto now = Clock::now(); - - if (now > m_started_at) - m_duration += now - m_started_at; - } - - u64 count() const { return m_calls_count; } - - u64 duration() const - { - using namespace std::chrono; - return u64(duration_cast(m_duration).count()); - } -}; - enum class CScriptProfilerType : u32 { None = 0, @@ -71,12 +16,8 @@ enum class CScriptProfilerType : u32 class XRSCRIPTENGINE_API CScriptProfiler { - using Clock = std::chrono::high_resolution_clock; - using Time = Clock::time_point; - using Duration = Clock::duration; - +// todo: Can we make some global module to store all the arguments as experessions? private: - // todo: Can we make some global module to store all the arguments as experessions? // List of commnad line args for startup profuler attach: constexpr static cpcstr ARGUMENT_PROFILER_DEFAULT = "-lua_profiler"; constexpr static cpcstr ARGUMENT_PROFILER_HOOK = "-lua_hook_profiler"; @@ -103,7 +44,7 @@ class XRSCRIPTENGINE_API CScriptProfiler */ u32 m_sampling_profile_interval; xr_unordered_map m_hook_profiling_portions; - xr_vector m_sampling_profiling_log; + xr_vector m_sampling_profiling_log; public: CScriptProfiler(CScriptEngine* engine); @@ -137,5 +78,6 @@ class XRSCRIPTENGINE_API CScriptProfiler static void luaJitSamplingProfilerAttach(CScriptProfiler* profiler, u32 interval); static void luaJitProfilerStart(lua_State* L, cpcstr mode, luaJIT_profile_callback callback, void* data); static void luaJitProfilerStop(lua_State* L); + static shared_str luaJitProfilerDumpToString(lua_State* L, cpcstr format, int depth); static std::pair luaJitProfilerDump(lua_State* L, cpcstr format, int depth); }; diff --git a/src/xrScriptEngine/script_profiler_portions.hpp b/src/xrScriptEngine/script_profiler_portions.hpp new file mode 100644 index 00000000000..9b081e61531 --- /dev/null +++ b/src/xrScriptEngine/script_profiler_portions.hpp @@ -0,0 +1,85 @@ +#pragma once +#include "pch.hpp" + +class CScriptProfilerHookPortion { + using Clock = std::chrono::high_resolution_clock; + using Time = Clock::time_point; + using Duration = Clock::duration; + + private: + u64 m_calls_count; + u32 m_calls_active; + + Time m_started_at; + Duration m_duration; + + public: + CScriptProfilerHookPortion(): m_calls_count(0), m_calls_active(0), m_duration(0), m_started_at() {} + + void start() + { + m_calls_count += 1; + + if (m_calls_active) + { + m_calls_active += 1; + return; + } + else + { + m_started_at = Clock::now(); + m_calls_active += 1; + } + } + + void stop() + { + if (!m_calls_active) + return; + + m_calls_active -= 1; + + if (m_calls_active) + return; + + const auto now = Clock::now(); + + if (now > m_started_at) + m_duration += now - m_started_at; + } + + u64 count() const { return m_calls_count; } + + u64 duration() const + { + using namespace std::chrono; + return u64(duration_cast(m_duration).count()); + } +}; + +class CScriptProfilerSamplingPortion { + using Clock = std::chrono::high_resolution_clock; + using Time = Clock::time_point; + + public: + Time tracked_at; + + int memory; + int samples; + int state; + shared_str name; + shared_str trace; + + CScriptProfilerSamplingPortion(shared_str name, shared_str trace, int samples, int state, int memory) + : name(name), trace(trace), memory(memory), samples(samples), state(state), tracked_at(Clock::now()) {} + + // Build flamechart folded stack including frames and samples count + // Example: `C;frame_1_func:24;frame_2_func:45 4` + shared_str getFoldedStack() + { + string2048 buffer; + xr_sprintf(buffer, "%c;%s %d", state, trace.c_str(), samples); + + return shared_str(buffer); + } +}; \ No newline at end of file diff --git a/src/xrScriptEngine/xrScriptEngine.vcxproj b/src/xrScriptEngine/xrScriptEngine.vcxproj index 4fdbd3bd804..015c5d753fd 100644 --- a/src/xrScriptEngine/xrScriptEngine.vcxproj +++ b/src/xrScriptEngine/xrScriptEngine.vcxproj @@ -51,6 +51,7 @@ + diff --git a/src/xrScriptEngine/xrScriptEngine.vcxproj.filters b/src/xrScriptEngine/xrScriptEngine.vcxproj.filters index 57b22e7e030..67e4aa3b5fd 100644 --- a/src/xrScriptEngine/xrScriptEngine.vcxproj.filters +++ b/src/xrScriptEngine/xrScriptEngine.vcxproj.filters @@ -48,6 +48,9 @@ Debug + + Debug + Debug From e750582e72dfc6ec527208bb3a754f4ff5e810a5 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Fri, 17 Jan 2025 21:19:28 +0200 Subject: [PATCH 12/24] Add comment with tracy exports. --- src/xrScriptEngine/ScriptEngineScript.cpp | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/src/xrScriptEngine/ScriptEngineScript.cpp b/src/xrScriptEngine/ScriptEngineScript.cpp index 927e212cc92..280cd270e37 100644 --- a/src/xrScriptEngine/ScriptEngineScript.cpp +++ b/src/xrScriptEngine/ScriptEngineScript.cpp @@ -208,4 +208,22 @@ SCRIPT_EXPORT(CScriptEngine, (), GEnv.ScriptEngine->m_profiler->saveReport(); }) ]; + + /** + * Exports injected from tracy profiler: + * + * https://github.com/wolfpld/tracy/blob/da60684b9f61b34afa5aa243a7838d6e79096783/manual/tracy.tex#L1932 + * https://github.com/wolfpld/tracy/blob/da60684b9f61b34afa5aa243a7838d6e79096783/public/tracy/TracyLua.hpp#L18 + * + * global tracy { + * function ZoneBegin; + * function ZoneBeginN; + * function ZoneBeginS; + * function ZoneBeginNS; + * function ZoneEnd; + * function ZoneText; + * function ZoneName; + * function Message; + * } + */ }); From 92203aadd872658ca4ef7cb09fef17cbe3bbe2c0 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Fri, 17 Jan 2025 23:27:59 +0200 Subject: [PATCH 13/24] Missing end line added. --- src/xrScriptEngine/script_profiler_portions.hpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/xrScriptEngine/script_profiler_portions.hpp b/src/xrScriptEngine/script_profiler_portions.hpp index 9b081e61531..76a4cf1479f 100644 --- a/src/xrScriptEngine/script_profiler_portions.hpp +++ b/src/xrScriptEngine/script_profiler_portions.hpp @@ -82,4 +82,4 @@ class CScriptProfilerSamplingPortion { return shared_str(buffer); } -}; \ No newline at end of file +}; From b8b348e8766edd18dc5331a397d0d64ec2691564 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Sat, 18 Jan 2025 03:21:08 +0200 Subject: [PATCH 14/24] Corrected hook profiler to make more sense. Add `luaDebugStackInfo`. --- src/xrScriptEngine/ScriptEngineScript.cpp | 6 +- src/xrScriptEngine/script_profiler.cpp | 253 ++++++++++-------- src/xrScriptEngine/script_profiler.hpp | 33 +-- .../script_profiler_portions.hpp | 29 +- 4 files changed, 174 insertions(+), 147 deletions(-) diff --git a/src/xrScriptEngine/ScriptEngineScript.cpp b/src/xrScriptEngine/ScriptEngineScript.cpp index 280cd270e37..53b9cf49153 100644 --- a/src/xrScriptEngine/ScriptEngineScript.cpp +++ b/src/xrScriptEngine/ScriptEngineScript.cpp @@ -183,13 +183,13 @@ SCRIPT_EXPORT(CScriptEngine, (), { GEnv.ScriptEngine->m_profiler->start(hook_type); }), - def("start_sampling_mode", +[](u32 sampling_interval) + def("start_sampling_mode", +[](u32 sampling_interval = CScriptProfiler::PROFILE_SAMPLING_INTERVAL_DEFAULT) { GEnv.ScriptEngine->m_profiler->startSamplingMode(sampling_interval); }), - def("start_hook_mode", +[](u32 stack_depth) + def("start_hook_mode", +[]() { - GEnv.ScriptEngine->m_profiler->startHookMode(stack_depth); + GEnv.ScriptEngine->m_profiler->startHookMode(); }), def("stop", +[]() { diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index 28b88d22d21..bfc521bd94b 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -9,13 +9,12 @@ CScriptProfiler::CScriptProfiler(CScriptEngine* engine) m_engine = engine; m_active = false; m_profiler_type = CScriptProfilerType::None; - m_sampling_profile_interval = PROFILE_SAMPLING_INTERVAL_DEFAULT; - m_hook_profile_depth = PROFILE_HOOK_DEPTH_DEFAULT; + m_sampling_profile_interval = PROFILE_SAMPLING_INTERVAL_DEFAULT; if (strstr(Core.Params, ARGUMENT_PROFILER_DEFAULT)) start(); - else if (strstr(Core.Params, ARGUMENT_PROFILER_HOOK)) - start(CScriptProfilerType::Hook); + else if (strstr(Core.Params, ARGUMENT_PROFILER_HOOK)) + start(CScriptProfilerType::Hook); else if (strstr(Core.Params, ARGUMENT_PROFILER_SAMPLING)) start(CScriptProfilerType::Sampling); } @@ -29,20 +28,20 @@ void CScriptProfiler::start(CScriptProfilerType profiler_type) { switch (profiler_type) { - case CScriptProfilerType::Hook: - startHookMode(PROFILE_HOOK_DEPTH_DEFAULT); - return; + case CScriptProfilerType::Hook: + startHookMode(); + return; case CScriptProfilerType::Sampling: - startSamplingMode(PROFILE_SAMPLING_INTERVAL_DEFAULT); - return; + startSamplingMode(PROFILE_SAMPLING_INTERVAL_DEFAULT); + return; case CScriptProfilerType::None: - Msg("[P] Tried to start none type profiler"); - return; + Msg("[P] Tried to start none type profiler"); + return; default: NODEFAULT; } } -void CScriptProfiler::startHookMode(u32 stack_depth) +void CScriptProfiler::startHookMode() { if (m_active) { @@ -52,28 +51,25 @@ void CScriptProfiler::startHookMode(u32 stack_depth) if (!lua()) { - Msg("[P] Activating hook profiler on lua engine start, waiting init"); + Msg("[P] Activating hook profiler on lua engine start, waiting init"); - m_profiler_type = CScriptProfilerType::Hook; - m_active = true; + m_profiler_type = CScriptProfilerType::Hook; + m_active = true; return; } - clamp(stack_depth, 0u, PROFILE_SAMPLING_INTERVAL_MAX); - if (!attachLuaHook()) { Msg("[P] Cannot start scripts hook profiler, hook was not set properly"); - return; + return; } - Msg("[P] Starting scripts hook profiler, depth: %d", stack_depth); + Msg("[P] Starting scripts hook profiler"); - m_hook_profile_depth = stack_depth; m_hook_profiling_portions.clear(); - m_profiler_type = CScriptProfilerType::Hook; - m_active = true; + m_profiler_type = CScriptProfilerType::Hook; + m_active = true; } void CScriptProfiler::startSamplingMode(u32 sampling_interval) @@ -87,15 +83,15 @@ void CScriptProfiler::startSamplingMode(u32 sampling_interval) if (!luaIsJitProfilerDefined(lua())) { Msg("[P] Cannot start scripts sampling profiler, jit module is not defined"); - return; + return; } if (!lua()) { - Msg("[P] Activating sampling profiler on lua engine start, waiting init"); + Msg("[P] Activating sampling profiler on lua engine start, waiting init"); - m_profiler_type = CScriptProfilerType::Sampling; - m_active = true; + m_profiler_type = CScriptProfilerType::Sampling; + m_active = true; return; } @@ -107,8 +103,8 @@ void CScriptProfiler::startSamplingMode(u32 sampling_interval) luaJitSamplingProfilerAttach(this, sampling_interval); m_sampling_profile_interval = sampling_interval; - m_profiler_type = CScriptProfilerType::Sampling; - m_active = true; + m_profiler_type = CScriptProfilerType::Sampling; + m_active = true; } void CScriptProfiler::stop() @@ -121,16 +117,16 @@ void CScriptProfiler::stop() switch (m_profiler_type) { - case CScriptProfilerType::Hook: + case CScriptProfilerType::Hook: Msg("[P] Stopping scripts hook profiler"); // Do not detach hook here, adding it means that it is already test run in the first place. - break; + break; case CScriptProfilerType::Sampling: { - Msg("[P] Stopping scripts sampling profiler"); + Msg("[P] Stopping scripts sampling profiler"); // Detach profiler from luajit, stop operation will be ignore anyway if it is stopped/captured by another VM. luaJitProfilerStop(lua()); - break; + break; } default: Msg("[P] Tried to stop none type profiler"); @@ -152,7 +148,7 @@ void CScriptProfiler::reset() void CScriptProfiler::logReport() { - switch (m_profiler_type) + switch (m_profiler_type) { case CScriptProfilerType::Hook: return logHookReport(); @@ -181,7 +177,6 @@ void CScriptProfiler::logHookReport() for (auto it = m_hook_profiling_portions.begin(); it != m_hook_profiling_portions.end(); it++) { entries.push_back(it); - total_count += it->second.count(); total_duration += it->second.duration(); } @@ -193,7 +188,6 @@ void CScriptProfiler::logHookReport() Msg("[P] ===="); u64 index = 0; - string512 buffer; std::sort(entries.begin(), entries.end(), [](auto& left, auto& right) { return left->second.duration() > right->second.duration(); }); @@ -237,46 +231,71 @@ void CScriptProfiler::logHookReport() Msg("[P] =================================================================="); FlushLog(); - - // todo; - // todo; - // todo; } void CScriptProfiler::logSamplingReport() { - // todo: Separete save method, implement printing function here. - // todo: Separete save method, implement printing function here. - // todo: Separete save method, implement printing function here. - if (m_sampling_profiling_log.empty()) { Msg("[P] Nothing to report for sampling profiler, data is missing"); return; } - string_path log_file_name; - strconcat(sizeof(log_file_name), log_file_name, Core.ApplicationName, "_", Core.UserName, "_sampling_profile.perf"); - FS.update_path(log_file_name, "$logs$", log_file_name); + u64 total_count = 0; + xr_unordered_map sampling_portions; - Msg("[P] Saving sampling report to %s", log_file_name); + for (auto it = m_sampling_profiling_log.begin(); it != m_sampling_profiling_log.end(); it++) + { + auto portion = sampling_portions.find(it->m_name); - IWriter* F = FS.w_open(log_file_name); + if (portion != sampling_portions.end()) + portion->second.m_samples += it->m_samples; + else + sampling_portions.emplace(it->m_name, it->cloned()); + } - if (F) - { - for (auto &it : m_sampling_profiling_log) - { - F->w_string(*it.getFoldedStack()); - } + xr_vector entries; + entries.reserve(sampling_portions.size()); - FS.w_close(F); + for (auto it = sampling_portions.begin(); it != sampling_portions.end(); it++) + { + entries.push_back(it); + total_count += it->second.m_samples; } + + std::sort(entries.begin(), entries.end(), + [](auto& left, auto& right) { return left->second.m_samples > right->second.m_samples; }); + + Msg("[P] =================================================================="); + Msg("[P] = Sampling profiler report, %d entries", entries.size()); + Msg("[P] =================================================================="); + Msg("[P] = By samples count:"); + Msg("[P] ===="); + + u64 index = 0; + + for (auto it = entries.begin(); it != entries.end(); it++) + { + if (index >= CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT) + break; + + Msg("[P] [%3d] %d (%5.2f%%) : %s", index, (*it)->second.m_samples, + ((f64)(*it)->second.m_samples * 100.0) / (f64)total_count, (*it)->first.c_str()); + + index += 1; + } + + Msg("[P] =================================================================="); + Msg("[P] = Total samples: %d", total_count); + Msg("[P] = Total function calls duration: %d ms (approximate)", total_count * m_sampling_profile_interval); + Msg("[P] =================================================================="); + + FlushLog(); } void CScriptProfiler::saveReport() { - switch (m_profiler_type) + switch (m_profiler_type) { case CScriptProfilerType::Hook: return saveHookReport(); @@ -291,7 +310,7 @@ void CScriptProfiler::saveReport() void CScriptProfiler::saveHookReport() { if (m_hook_profiling_portions.empty()) - { + { Msg("[P] Nothing to report for hook profiler, data is missing"); return; } @@ -305,31 +324,44 @@ void CScriptProfiler::saveHookReport() void CScriptProfiler::saveSamplingReport() { - if (m_sampling_profiling_log.empty()) - { + if (m_sampling_profiling_log.empty()) + { Msg("[P] Nothing to report for sampling profiler, data is missing"); return; } - string_path log_file_name; - strconcat(sizeof(log_file_name), log_file_name, Core.ApplicationName, "_", Core.UserName, "_sampling_profile.perf"); - FS.update_path(log_file_name, "$logs$", log_file_name); - - Msg("[P] Saving sampling report to %s", log_file_name); + shared_str log_file_name = getSamplingReportFilename(); + IWriter* F = FS.w_open(log_file_name.c_str()); - IWriter* F = FS.w_open(log_file_name); + Msg("[P] Saving sampling report to %s", log_file_name.c_str()); if (F) { for (auto &it : m_sampling_profiling_log) - { F->w_string(*it.getFoldedStack()); - } FS.w_close(F); } } +shared_str CScriptProfiler::getHookReportFilename() +{ + string_path log_file_name; + strconcat(sizeof(log_file_name), log_file_name, Core.ApplicationName, "_", Core.UserName, "_hook_profile.log"); + FS.update_path(log_file_name, "$logs$", log_file_name); + + return log_file_name; +} + +shared_str CScriptProfiler::getSamplingReportFilename() +{ + string_path log_file_name; + strconcat(sizeof(log_file_name), log_file_name, Core.ApplicationName, "_", Core.UserName, "_sampling_profile.perf"); + FS.update_path(log_file_name, "$logs$", log_file_name); + + return log_file_name; +} + /* * @returns whether profiling lua hook was/is attached to current VM context */ @@ -337,7 +369,11 @@ bool CScriptProfiler::attachLuaHook() { lua_Hook hook = lua_gethook(lua()); - return hook ? hook == CScriptEngine::lua_hook_call : lua_sethook(lua(), CScriptEngine::lua_hook_call, LUA_MASKLINE | LUA_MASKCALL | LUA_MASKRET, 0); + // Do not rewrite active hooks and verify if correct hooks is set. + if (hook) + return hook == CScriptEngine::lua_hook_call; + else + return lua_sethook(lua(), CScriptEngine::lua_hook_call, LUA_MASKLINE | LUA_MASKCALL | LUA_MASKRET, 0); } void CScriptProfiler::onDispose(lua_State* L) @@ -347,43 +383,43 @@ void CScriptProfiler::onDispose(lua_State* L) if (m_active && m_profiler_type == CScriptProfilerType::Sampling) { Msg("[P] Disposing sampling dependencies"); - luaJitProfilerStop(L); + luaJitProfilerStop(L); } } void CScriptProfiler::onReinit(lua_State* L) { if (!m_active) - return; + return; - Msg("[P] Profiler reinit %d", lua()); + Msg("[P] Profiler reinit %d", lua()); switch (m_profiler_type) { - case CScriptProfilerType::Hook: - if (!attachLuaHook()) + case CScriptProfilerType::Hook: + if (!attachLuaHook()) { - Msg("[P] Cannot start scripts hook profiler on reinit, hook was not set properly"); - return; + Msg("[P] Cannot start scripts hook profiler on reinit, hook was not set properly"); + return; } - Msg("[P] Reinit scripts hook profiler"); + Msg("[P] Reinit scripts hook profiler"); m_hook_profiling_portions.clear(); - return; + return; case CScriptProfilerType::Sampling: { if (!luaIsJitProfilerDefined(lua())) { - Msg("[P] Cannot start scripts sampling profiler on reinit, jit.profiler module is not defined"); - return; + Msg("[P] Cannot start scripts sampling profiler on reinit, jit.profiler module is not defined"); + return; } Msg("[P] Re-init scripts sampling profiler - attach handler, interval: %d", m_sampling_profile_interval); - luaJitSamplingProfilerAttach(this, m_sampling_profile_interval); + luaJitSamplingProfilerAttach(this, m_sampling_profile_interval); - return; + return; } default: NODEFAULT; @@ -395,45 +431,23 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) if (!m_active || m_profiler_type != CScriptProfilerType::Hook || dbg->event == LUA_HOOKLINE) return; - lua_Debug parent_stack_info; - lua_Debug stack_info; - - // todo: Implement dynamic depth. - // todo: Implement dynamic depth. - - // Check higher level of stack. - if (m_hook_profile_depth > 0) - { - if (!lua_getstack(L, 1, &parent_stack_info)) - { - return; - } - - lua_getinfo(L, "nSl", &parent_stack_info); - } + auto [parent_stack_info, has_parent_stack_info] = luaDebugStackInfo(L, 2, "nSl"); + auto [stack_info, has_stack_info] = luaDebugStackInfo(L, 1, "nSl"); - if (!lua_getstack(L, 0, &stack_info)) - { + if (!has_parent_stack_info || !has_stack_info) return; - } - - lua_getinfo(L, "nSl", &stack_info); string512 buffer; auto name = stack_info.name ? stack_info.name : "?"; - auto parent_name = m_hook_profile_depth > 0 && parent_stack_info.name ? parent_stack_info.name : "?"; + auto parent_name = parent_stack_info.name ? parent_stack_info.name : "[C]"; auto short_src = stack_info.short_src; auto line_defined = stack_info.linedefined; if (!stack_info.name && line_defined == 0) name = "lua-script-body"; - // Include date from higher stack levels. - if (m_hook_profile_depth > 0) - xr_sprintf(buffer, "%s [%d] - %s @ %s", name, line_defined, parent_name, short_src); - else - xr_sprintf(buffer, "%s [%d] @ %s", name, line_defined, parent_name, short_src); + xr_sprintf(buffer, "%s [%d] - %s @ %s", name, line_defined, parent_name, short_src); auto it = m_hook_profiling_portions.find(buffer); bool exists = it != m_hook_profiling_portions.end(); @@ -489,7 +503,7 @@ lua_State* CScriptProfiler::lua() const */ int CScriptProfiler::luaMemoryUsed(lua_State* L) { - return lua_gc(L, LUA_GCCOUNT, 0) * 1024 + lua_gc(L, LUA_GCCOUNTB, 0); + return lua_gc(L, LUA_GCCOUNT, 0) * 1024 + lua_gc(L, LUA_GCCOUNTB, 0); } /* @@ -509,7 +523,7 @@ bool CScriptProfiler::luaIsJitProfilerDefined(lua_State* L) */ void CScriptProfiler::luaJitSamplingProfilerAttach(CScriptProfiler* profiler, u32 interval) { - string32 buffer = "fli"; + string32 buffer = "fli"; xr_itoa(interval, buffer + 3, 10); luaJitProfilerStart( @@ -563,8 +577,8 @@ void CScriptProfiler::luaJitProfilerStop(lua_State* L) */ shared_str CScriptProfiler::luaJitProfilerDumpToString(lua_State* L, cpcstr format, int depth) { - string2048 buffer; - size_t length; + string2048 buffer; + size_t length; cpcstr dump = luaJIT_profile_dumpstack(L, format, depth, &length); R_ASSERT2(length < 2048, "Profiling dump buffer overflow"); @@ -586,8 +600,21 @@ shared_str CScriptProfiler::luaJitProfilerDumpToString(lua_State* L, cpcstr form */ std::pair CScriptProfiler::luaJitProfilerDump(lua_State* L, cpcstr format, int depth) { - size_t length; + size_t length; cpcstr dump = luaJIT_profile_dumpstack(L, format, depth, &length); return std::make_pair(dump, length); } + +std::pair CScriptProfiler::luaDebugStackInfo(lua_State* L, int level, cpcstr what) +{ + lua_Debug info; + bool has_stack = lua_getstack(L, level, &info); + + if (has_stack) + { + lua_getinfo(L, what, &info); + } + + return std::make_pair(std::move(info), has_stack); +} diff --git a/src/xrScriptEngine/script_profiler.hpp b/src/xrScriptEngine/script_profiler.hpp index 43c8dcf9d71..c2b80176ac1 100644 --- a/src/xrScriptEngine/script_profiler.hpp +++ b/src/xrScriptEngine/script_profiler.hpp @@ -17,67 +17,60 @@ enum class CScriptProfilerType : u32 class XRSCRIPTENGINE_API CScriptProfiler { // todo: Can we make some global module to store all the arguments as experessions? -private: +public: // List of commnad line args for startup profuler attach: constexpr static cpcstr ARGUMENT_PROFILER_DEFAULT = "-lua_profiler"; constexpr static cpcstr ARGUMENT_PROFILER_HOOK = "-lua_hook_profiler"; constexpr static cpcstr ARGUMENT_PROFILER_SAMPLING = "-lua_sampling_profiler"; static const u32 PROFILE_ENTRIES_LOG_LIMIT = 128; - static const u32 PROFILE_HOOK_DEPTH_DEFAULT = 1; - static const u32 PROFILE_HOOK_DEPTH_MAX = 1; - static const u32 PROFILE_SAMPLING_INTERVAL_DEFAULT = 10; + static const u32 PROFILE_SAMPLING_INTERVAL_DEFAULT = 1; static const u32 PROFILE_SAMPLING_INTERVAL_MAX = 1000; +private: CScriptEngine* m_engine; CScriptProfilerType m_profiler_type; bool m_active; - - /* - * Profiling depth - number of stacks to summarise function call trace. - * Helps validating results of same functions called from different places vs totals by specific function. - */ - u32 m_hook_profile_depth; /* * Sampling interval for JIT based profiler. * Value should be set in ms and defaults to 10ms. */ - u32 m_sampling_profile_interval; xr_unordered_map m_hook_profiling_portions; xr_vector m_sampling_profiling_log; + u32 m_sampling_profile_interval; public: CScriptProfiler(CScriptEngine* engine); virtual ~CScriptProfiler(); bool isActive() const { return m_active; }; - - void start(CScriptProfilerType profiler_type = CScriptProfilerType::Hook); + void start(CScriptProfilerType profiler_type = CScriptProfilerType::Hook); void startSamplingMode(u32 sampling_interval); - void startHookMode(u32 stack_depth); + void startHookMode(); void stop(); void reset(); - void logReport(); void logHookReport(); void logSamplingReport(); void saveReport(); void saveHookReport(); void saveSamplingReport(); + shared_str getHookReportFilename(); + shared_str getSamplingReportFilename(); - void onReinit(lua_State* L); - void onDispose(lua_State* L); + bool attachLuaHook(); + void onReinit(lua_State* L); + void onDispose(lua_State* L); void onLuaHookCall(lua_State* L, lua_Debug* dbg); private: lua_State* lua() const; - bool attachLuaHook(); - - static int luaMemoryUsed(lua_State* L); + static int luaMemoryUsed(lua_State* L); static bool luaIsJitProfilerDefined(lua_State* L); static void luaJitSamplingProfilerAttach(CScriptProfiler* profiler, u32 interval); static void luaJitProfilerStart(lua_State* L, cpcstr mode, luaJIT_profile_callback callback, void* data); static void luaJitProfilerStop(lua_State* L); static shared_str luaJitProfilerDumpToString(lua_State* L, cpcstr format, int depth); static std::pair luaJitProfilerDump(lua_State* L, cpcstr format, int depth); + static std::pair luaDebugStackInfo(lua_State* L, int level, cpcstr what); }; diff --git a/src/xrScriptEngine/script_profiler_portions.hpp b/src/xrScriptEngine/script_profiler_portions.hpp index 76a4cf1479f..956d925551c 100644 --- a/src/xrScriptEngine/script_profiler_portions.hpp +++ b/src/xrScriptEngine/script_profiler_portions.hpp @@ -58,28 +58,35 @@ class CScriptProfilerHookPortion { }; class CScriptProfilerSamplingPortion { - using Clock = std::chrono::high_resolution_clock; + using Clock = std::chrono::high_resolution_clock; using Time = Clock::time_point; - public: - Time tracked_at; + public: + Time m_recoreded_at; - int memory; - int samples; - int state; - shared_str name; - shared_str trace; + int m_memory; + int m_samples; + int m_state; + shared_str m_name; + shared_str m_trace; CScriptProfilerSamplingPortion(shared_str name, shared_str trace, int samples, int state, int memory) - : name(name), trace(trace), memory(memory), samples(samples), state(state), tracked_at(Clock::now()) {} + : m_name(name), m_trace(trace), m_memory(memory), m_samples(samples), m_state(state), + m_recoreded_at(Clock::now()) {} + + CScriptProfilerSamplingPortion(const CScriptProfilerSamplingPortion& rhs) + : m_name(rhs.m_name), m_trace(rhs.m_trace), m_memory(rhs.m_memory), m_samples(rhs.m_samples), + m_state(rhs.m_state), m_recoreded_at(rhs.m_recoreded_at) {} + + CScriptProfilerSamplingPortion cloned() const { return CScriptProfilerSamplingPortion(*this); } // Build flamechart folded stack including frames and samples count // Example: `C;frame_1_func:24;frame_2_func:45 4` shared_str getFoldedStack() { string2048 buffer; - xr_sprintf(buffer, "%c;%s %d", state, trace.c_str(), samples); + xr_sprintf(buffer, "%c;%s %d", m_state, m_trace.c_str(), m_samples); - return shared_str(buffer); + return shared_str(buffer); } }; From 7831405ddad63ef36cddbfc6360ed401821d898f Mon Sep 17 00:00:00 2001 From: Neloreck Date: Sat, 18 Jan 2025 05:38:42 +0200 Subject: [PATCH 15/24] Adjust report generation format/building. --- src/xrScriptEngine/script_engine.cpp | 8 +- src/xrScriptEngine/script_profiler.cpp | 178 ++++++++++++++----------- 2 files changed, 102 insertions(+), 84 deletions(-) diff --git a/src/xrScriptEngine/script_engine.cpp b/src/xrScriptEngine/script_engine.cpp index 24f81799706..931c1f7c0b4 100644 --- a/src/xrScriptEngine/script_engine.cpp +++ b/src/xrScriptEngine/script_engine.cpp @@ -119,9 +119,9 @@ void CScriptEngine::reinit() if (m_virtual_machine) { if (m_profiler) - m_profiler->onDispose(m_virtual_machine); + m_profiler->onDispose(m_virtual_machine); - lua_close(m_virtual_machine); + lua_close(m_virtual_machine); UnregisterState(m_virtual_machine); } m_virtual_machine = lua_newstate(lua_alloc, nullptr); @@ -139,7 +139,7 @@ void CScriptEngine::reinit() scriptBuffer = xr_alloc(scriptBufferSize); if (m_profiler) - m_profiler->onReinit(m_virtual_machine); + m_profiler->onReinit(m_virtual_machine); } void CScriptEngine::print_stack(lua_State* L) @@ -903,7 +903,7 @@ void CScriptEngine::lua_hook_call(lua_State* L, lua_Debug* dbg) #endif if (scriptEngine->m_profiler) - scriptEngine->m_profiler->onLuaHookCall(L, dbg); + scriptEngine->m_profiler->onLuaHookCall(L, dbg); } int CScriptEngine::auto_load(lua_State* L) diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index bfc521bd94b..3eb7cd771df 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -181,56 +181,57 @@ void CScriptProfiler::logHookReport() total_duration += it->second.duration(); } - Msg("[P] =================================================================="); - Msg("[P] = Hook profiler report, %d entries", entries.size()); - Msg("[P] =================================================================="); - Msg("[P] = By calls duration:"); - Msg("[P] ===="); + Msg("[P] =================================================================="); + Msg("[P] = Hook profiler report, %d entries", entries.size()); + Msg("[P] =================================================================="); + Msg("[P] = By calls duration:"); + Msg("[P] =================================================================="); + Msg("[P] [idx] sum sum%% | calls avg | trace"); - u64 index = 0; + u64 index = 0; - std::sort(entries.begin(), entries.end(), - [](auto& left, auto& right) { return left->second.duration() > right->second.duration(); }); + std::sort(entries.begin(), entries.end(), + [](auto& left, auto& right) { return left->second.duration() > right->second.duration(); }); - for (auto it = entries.begin(); it != entries.end(); it++) - { - if (index >= CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT) - break; + for (auto it = entries.begin(); it != entries.end(); it++) + { + if (index >= CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT) + break; - Msg("[P] [%3d] %6.3f ms (%5.2f%%) %6d calls, %6.3f ms avg : %s", index, (*it)->second.duration() / 1000.0, - ((f64)(*it)->second.duration() * 100.0) / (f64)total_duration, (*it)->second.count(), - (f64)(*it)->second.duration() / (f64)(*it)->second.count() / 1000.0, - (*it)->first.c_str()); + Msg("[P] [%3d] %9.3f ms %5.2f%% | %9d %9.3f ms | %s", index, (*it)->second.duration() / 1000.0, + ((f64)(*it)->second.duration() * 100.0) / (f64)total_duration, (*it)->second.count(), + (f64)(*it)->second.duration() / (f64)(*it)->second.count() / 1000.0, (*it)->first.c_str()); - index += 1; - } + index += 1; + } - Msg("[P] =================================================================="); - Msg("[P] = By calls count:"); - Msg("[P] ===="); + Msg("[P] =================================================================="); + Msg("[P] = By calls count:"); + Msg("[P] =================================================================="); + Msg("[P] [idx] calls calls%% | trace"); - index = 0; + index = 0; - std::sort(entries.begin(), entries.end(), - [](auto& left, auto& right) { return left->second.count() > right->second.count(); }); + std::sort(entries.begin(), entries.end(), + [](auto& left, auto& right) { return left->second.count() > right->second.count(); }); - for (auto it = entries.begin(); it != entries.end(); it++) - { - if (index >= CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT) - break; + for (auto it = entries.begin(); it != entries.end(); it++) + { + if (index >= CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT) + break; - Msg("[P] [%3d] %6d (%5.2f%%) : %s", index, (*it)->second.count(), - ((f64)(*it)->second.count() * 100.0) / (f64)total_count, (*it)->first.c_str()); + Msg("[P] [%3d] %9d %5.2f%% | %s", index, (*it)->second.count(), + ((f64)(*it)->second.count() * 100.0) / (f64)total_count, (*it)->first.c_str()); - index += 1; - } + index += 1; + } - Msg("[P] =================================================================="); - Msg("[P] = Total function calls count: %d", total_count); - Msg("[P] = Total function calls duration: %f ms", (f32) total_duration / 1000.0); - Msg("[P] =================================================================="); + Msg("[P] =================================================================="); + Msg("[P] = Total function calls count: %d", total_count); + Msg("[P] = Total function calls duration: %f ms", (f32) total_duration / 1000.0); + Msg("[P] =================================================================="); - FlushLog(); + FlushLog(); } void CScriptProfiler::logSamplingReport() @@ -263,34 +264,33 @@ void CScriptProfiler::logSamplingReport() total_count += it->second.m_samples; } - std::sort(entries.begin(), entries.end(), - [](auto& left, auto& right) { return left->second.m_samples > right->second.m_samples; }); + std::sort(entries.begin(), entries.end(), + [](auto& left, auto& right) { return left->second.m_samples > right->second.m_samples; }); - Msg("[P] =================================================================="); - Msg("[P] = Sampling profiler report, %d entries", entries.size()); - Msg("[P] =================================================================="); - Msg("[P] = By samples count:"); - Msg("[P] ===="); + Msg("[P] =================================================================="); + Msg("[P] = Sampling profiler report, %d entries", entries.size()); + Msg("[P] =================================================================="); + Msg("[P] [idx] samples %% | trace"); - u64 index = 0; + u64 index = 0; - for (auto it = entries.begin(); it != entries.end(); it++) - { - if (index >= CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT) - break; + for (auto it = entries.begin(); it != entries.end(); it++) + { + if (index >= CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT) + break; - Msg("[P] [%3d] %d (%5.2f%%) : %s", index, (*it)->second.m_samples, - ((f64)(*it)->second.m_samples * 100.0) / (f64)total_count, (*it)->first.c_str()); + Msg("[P] [%3d] %9d %5.2f%% | %s", index, (*it)->second.m_samples, + ((f64)(*it)->second.m_samples * 100.0) / (f64)total_count, (*it)->first.c_str()); - index += 1; - } + index += 1; + } - Msg("[P] =================================================================="); - Msg("[P] = Total samples: %d", total_count); - Msg("[P] = Total function calls duration: %d ms (approximate)", total_count * m_sampling_profile_interval); - Msg("[P] =================================================================="); + Msg("[P] =================================================================="); + Msg("[P] = Total samples: %d", total_count); + Msg("[P] = Total function calls duration: %d ms (approximate)", total_count * m_sampling_profile_interval); + Msg("[P] =================================================================="); - FlushLog(); + FlushLog(); } void CScriptProfiler::saveReport() @@ -315,11 +315,33 @@ void CScriptProfiler::saveHookReport() return; } - Log("[P] Saving hook profiler report"); + shared_str log_file_name = getHookReportFilename(); + IWriter* F = FS.w_open(log_file_name.c_str()); + + Msg("[P] Saving hook report to %s", log_file_name.c_str()); + + xr_vector entries; + entries.reserve(m_hook_profiling_portions.size()); + + for (auto it = m_hook_profiling_portions.begin(); it != m_hook_profiling_portions.end(); it++) + entries.push_back(it); + + std::sort(entries.begin(), entries.end(), + [](auto& left, auto& right) { return left->second.duration() > right->second.duration(); }); - // todo; - // todo; - // todo; + if (F) + { + string2048 buffer; + + for (auto &it : entries) + { + xr_sprintf(buffer, "trace:%s calls:%d avg:%.3fms sum:%.3fms ", it->first.c_str(), it->second.count(), + (f32)it->second.duration() / (f32)it->second.count() / 1000.0, it->second.duration() / 1000.0); + F->w_string(buffer); + } + + FS.w_close(F); + } } void CScriptProfiler::saveSamplingReport() @@ -433,21 +455,31 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) auto [parent_stack_info, has_parent_stack_info] = luaDebugStackInfo(L, 2, "nSl"); auto [stack_info, has_stack_info] = luaDebugStackInfo(L, 1, "nSl"); + auto [at_stack_info, has_at_stack_info] = luaDebugStackInfo(L, 0, "nSl"); if (!has_parent_stack_info || !has_stack_info) return; string512 buffer; - auto name = stack_info.name ? stack_info.name : "?"; + auto name = stack_info.name ? stack_info.name : at_stack_info.name ; auto parent_name = parent_stack_info.name ? parent_stack_info.name : "[C]"; auto short_src = stack_info.short_src; + auto parent_short_src = parent_stack_info.short_src; auto line_defined = stack_info.linedefined; + auto parent_line_defined = parent_stack_info.linedefined; + + if (!name) + name = "?"; if (!stack_info.name && line_defined == 0) - name = "lua-script-body"; + name = "script-body"; - xr_sprintf(buffer, "%s [%d] - %s @ %s", name, line_defined, parent_name, short_src); + if (xr_strcmp(short_src, parent_short_src) == 0) + xr_sprintf(buffer, "%s:%d;%s@%s:%d", name, line_defined, parent_name, parent_short_src, parent_line_defined); + else + xr_sprintf(buffer, "%s@%s:%d;%s@%s:%d", name, short_src, line_defined, parent_name, parent_short_src, + parent_line_defined); auto it = m_hook_profiling_portions.find(buffer); bool exists = it != m_hook_profiling_portions.end(); @@ -457,9 +489,7 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) case LUA_HOOKCALL: { if (exists) - { it->second.start(); - } else { CScriptProfilerHookPortion portion; @@ -472,20 +502,10 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) return; } case LUA_HOOKRET: - { - if (exists) - { - it->second.stop(); - } - - return; - } case LUA_HOOKTAILRET: { if (exists) - { it->second.stop(); - } return; } @@ -557,7 +577,6 @@ void CScriptProfiler::luaJitProfilerStart(lua_State* L, cpcstr mode, luaJIT_prof { // Only single JIT profiler can exist and it will not attach with multiple states. // Also only VM started profiler can end it, be careful. - luaJIT_profile_start(L, mode, callback, data); } @@ -581,8 +600,7 @@ shared_str CScriptProfiler::luaJitProfilerDumpToString(lua_State* L, cpcstr form size_t length; cpcstr dump = luaJIT_profile_dumpstack(L, format, depth, &length); - R_ASSERT2(length < 2048, "Profiling dump buffer overflow"); - + R_ASSERT2(length < sizeof(buffer), "Profiling dump buffer overflow"); strncpy_s(buffer, sizeof(buffer), dump, length); buffer[length] = 0; From b7200ae6313a529a574f2f9a0d47456bb2faee35 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Sat, 18 Jan 2025 21:33:12 +0200 Subject: [PATCH 16/24] Add lua profiler console commands. --- src/xrGame/console_commands.cpp | 117 ++++++++++++++++++++++ src/xrScriptEngine/ScriptEngineScript.cpp | 28 +++--- src/xrScriptEngine/script_profiler.cpp | 82 ++++++++++----- src/xrScriptEngine/script_profiler.hpp | 26 +++-- 4 files changed, 201 insertions(+), 52 deletions(-) diff --git a/src/xrGame/console_commands.cpp b/src/xrGame/console_commands.cpp index 09adc0af537..8f11bdac353 100644 --- a/src/xrGame/console_commands.cpp +++ b/src/xrGame/console_commands.cpp @@ -1992,6 +1992,115 @@ class CCC_UI_Time_Factor : public IConsole_Command } }; +class CCC_LuaProfiler : public IConsole_Command +{ +public: + CCC_LuaProfiler(LPCSTR N) : IConsole_Command(N) { bEmptyArgsHandled = true; }; + virtual void Execute(LPCSTR args) + { + + if (strstr(cName, "lua_profiler_start_hook_mode") == cName) + { + GEnv.ScriptEngine->m_profiler->startHookMode(); + } + else if (strstr(cName, "lua_profiler_start_sampling_mode") == cName) + { + u32 interval = atoi(args); + + GEnv.ScriptEngine->m_profiler->startSamplingMode( + interval ? interval : CScriptProfiler::PROFILE_SAMPLING_INTERVAL_DEFAULT); + } + else if (strstr(cName, "lua_profiler_start") == cName) + { + u32 profiler_type = atoi(args); + + GEnv.ScriptEngine->m_profiler->start( + (profiler_type ? (CScriptProfilerType)profiler_type : CScriptProfiler::PROFILE_TYPE_DEFAULT)); + } + else if (strstr(cName, "lua_profiler_stop") == cName) + { + GEnv.ScriptEngine->m_profiler->stop(); + } + else if (strstr(cName, "lua_profiler_reset") == cName) + { + GEnv.ScriptEngine->m_profiler->reset(); + } + else if (strstr(cName, "lua_profiler_log") == cName) + { + u32 limit = atoi(args); + + GEnv.ScriptEngine->m_profiler->logReport( + limit ? limit : CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT_DEFAULT); + } + else if (strstr(cName, "lua_profiler_save") == cName) + { + GEnv.ScriptEngine->m_profiler->saveReport(); + } + }; + + void fill_tips(vecTips& tips, u32 /*mode*/) override + { + CScriptProfiler* profiler = GEnv.ScriptEngine->m_profiler; + TStatus status_buffer; + + + if (strstr(cName, "lua_profiler_start_hook_mode") == cName) + { + // No arguments. + } + else if (strstr(cName, "lua_profiler_start_sampling_mode") == cName) + { + xr_sprintf(status_buffer, "%d (default) [1-%d] - sampling interval", + CScriptProfiler::PROFILE_SAMPLING_INTERVAL_DEFAULT, CScriptProfiler::PROFILE_SAMPLING_INTERVAL_MAX); + tips.push_back(status_buffer); + } + else if (strstr(cName, "lua_profiler_start") == cName) + { + xr_sprintf(status_buffer, "%d - hooks based profiler", CScriptProfilerType::Hook); + tips.push_back(status_buffer); + + xr_sprintf(status_buffer, "%d - sampling based profiler", CScriptProfilerType::Sampling); + tips.push_back(status_buffer); + } + else if (strstr(cName, "lua_profiler_stop") == cName) + { + // No arguments. + } + else if (strstr(cName, "lua_profiler_reset") == cName) + { + // No arguments. + } + else if (strstr(cName, "lua_profiler_log") == cName) + { + xr_sprintf(status_buffer, "%d (default) - count of profiling entries to print", + CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT_DEFAULT, CScriptProfiler::PROFILE_SAMPLING_INTERVAL_MAX); + tips.push_back(status_buffer); + } + else if (strstr(cName, "lua_profiler_save") == cName) + { + // No arguments. + } + } + + void Info(TInfo& I) override + { + if (strstr(cName, "lua_profiler_start_hook_mode") == cName) + xr_strcpy(I, "no arguments : start lua script profiling in hook mode"); + else if (strstr(cName, "lua_profiler_start_sampling_mode") == cName) + xr_strcpy(I, "integer value in range [1,1000] : start lua script profiling in sampling mode with provided sampling interval"); + else if (strstr(cName, "lua_profiler_start") == cName) + xr_strcpy(I, "integer value in range [0,2] : start lua script profiling in provided mode"); + else if (strstr(cName, "lua_profiler_stop") == cName) + xr_strcpy(I, "no arguments : stop lua script profiling"); + else if (strstr(cName, "lua_profiler_reset") == cName) + xr_strcpy(I, "no arguments : reset lua script profiling stats"); + else if (strstr(cName, "lua_profiler_log") == cName) + xr_strcpy(I, "integer value : log lua script profiling stats, limit entries with argument"); + else if (strstr(cName, "lua_profiler_save") == cName) + xr_strcpy(I, "no arguments : save lua script profiling stats in a file"); + } +}; + void CCC_RegisterCommands() { ZoneScoped; @@ -2076,6 +2185,14 @@ void CCC_RegisterCommands() CMD3(CCC_Mask, "lua_debug", &g_LuaDebug, 1); #endif // MASTER_GOLD + CMD1(CCC_LuaProfiler, "lua_profiler_start"); + CMD1(CCC_LuaProfiler, "lua_profiler_start_sampling_mode"); + CMD1(CCC_LuaProfiler, "lua_profiler_start_hook_mode"); + CMD1(CCC_LuaProfiler, "lua_profiler_stop"); + CMD1(CCC_LuaProfiler, "lua_profiler_reset"); + CMD1(CCC_LuaProfiler, "lua_profiler_log"); + CMD1(CCC_LuaProfiler, "lua_profiler_save"); + #ifdef DEBUG CMD4(CCC_Integer, "lua_gcstep", &psLUA_GCSTEP, 1, 1000); CMD3(CCC_Mask, "ai_debug", &psAI_Flags, aiDebug); diff --git a/src/xrScriptEngine/ScriptEngineScript.cpp b/src/xrScriptEngine/ScriptEngineScript.cpp index 53b9cf49153..fd1055dc89d 100644 --- a/src/xrScriptEngine/ScriptEngineScript.cpp +++ b/src/xrScriptEngine/ScriptEngineScript.cpp @@ -1,9 +1,9 @@ //////////////////////////////////////////////////////////////////////////// -// Module : script_engine_script.cpp -// Created : 25.12.2002 -// Modified : 13.05.2004 -// Author : Dmitriy Iassenev -// Description : ALife Simulator script engine export +// Module : script_engine_script.cpp +// Created : 25.12.2002 +// Modified : 13.05.2004 +// Author : Dmitriy Iassenev +// Description : ALife Simulator script engine export //////////////////////////////////////////////////////////////////////////// #include "pch.hpp" @@ -175,11 +175,7 @@ SCRIPT_EXPORT(CScriptEngine, (), { GEnv.ScriptEngine->m_profiler->isActive(); }), - def("start", +[]() - { - GEnv.ScriptEngine->m_profiler->start(); - }), - def("start", +[](CScriptProfilerType hook_type) + def("start", +[](CScriptProfilerType hook_type = CScriptProfilerType::None) { GEnv.ScriptEngine->m_profiler->start(hook_type); }), @@ -199,9 +195,9 @@ SCRIPT_EXPORT(CScriptEngine, (), { GEnv.ScriptEngine->m_profiler->reset(); }), - def("log_report", +[]() + def("log_report", +[](u32 entries_limit = CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT_DEFAULT) { - GEnv.ScriptEngine->m_profiler->logReport(); + GEnv.ScriptEngine->m_profiler->logReport(entries_limit); }), def("save_report", +[]() { @@ -210,12 +206,12 @@ SCRIPT_EXPORT(CScriptEngine, (), ]; /** - * Exports injected from tracy profiler: + * Exports injected from tracy profiler: * * https://github.com/wolfpld/tracy/blob/da60684b9f61b34afa5aa243a7838d6e79096783/manual/tracy.tex#L1932 * https://github.com/wolfpld/tracy/blob/da60684b9f61b34afa5aa243a7838d6e79096783/public/tracy/TracyLua.hpp#L18 * - * global tracy { + * global tracy { * function ZoneBegin; * function ZoneBeginN; * function ZoneBeginS; @@ -224,6 +220,6 @@ SCRIPT_EXPORT(CScriptEngine, (), * function ZoneText; * function ZoneName; * function Message; - * } - */ + * } + */ }); diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index 3eb7cd771df..01145fa757d 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -24,6 +24,34 @@ CScriptProfiler::~CScriptProfiler() m_engine = nullptr; } +shared_str CScriptProfiler::getTypeString() const +{ + switch (m_profiler_type) + { + case CScriptProfilerType::None: + return "None"; + case CScriptProfilerType::Hook: + return "Hook"; + case CScriptProfilerType::Sampling: + return "Sampling"; + default: NODEFAULT; + } +}; + +u32 CScriptProfiler::getRecordsCount() const +{ + switch (m_profiler_type) + { + case CScriptProfilerType::None: + return 0; + case CScriptProfilerType::Hook: + return m_hook_profiling_portions.size(); + case CScriptProfilerType::Sampling: + return m_sampling_profiling_log.size(); + default: NODEFAULT; + } +}; + void CScriptProfiler::start(CScriptProfilerType profiler_type) { switch (profiler_type) @@ -37,7 +65,9 @@ void CScriptProfiler::start(CScriptProfilerType profiler_type) case CScriptProfilerType::None: Msg("[P] Tried to start none type profiler"); return; - default: NODEFAULT; + default: + Msg("[P] Tried to start unknown type (%d) profiler", profiler_type); + return; } } @@ -146,21 +176,21 @@ void CScriptProfiler::reset() m_sampling_profiling_log.clear(); } -void CScriptProfiler::logReport() +void CScriptProfiler::logReport(u32 entries_limit) { switch (m_profiler_type) { - case CScriptProfilerType::Hook: - return logHookReport(); - case CScriptProfilerType::Sampling: - return logSamplingReport(); - default: - Msg("[P] No active profiling data to report"); - return; + case CScriptProfilerType::Hook: + return logHookReport(entries_limit); + case CScriptProfilerType::Sampling: + return logSamplingReport(entries_limit); + default: + Msg("[P] No active profiling data to report"); + return; } } -void CScriptProfiler::logHookReport() +void CScriptProfiler::logHookReport(u32 entries_limit) { if (m_hook_profiling_portions.empty()) { @@ -186,7 +216,7 @@ void CScriptProfiler::logHookReport() Msg("[P] =================================================================="); Msg("[P] = By calls duration:"); Msg("[P] =================================================================="); - Msg("[P] [idx] sum sum%% | calls avg | trace"); + Msg("[P] [idx] sum sum%% avg | calls | trace"); u64 index = 0; @@ -195,12 +225,13 @@ void CScriptProfiler::logHookReport() for (auto it = entries.begin(); it != entries.end(); it++) { - if (index >= CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT) + if (index >= entries_limit) break; - Msg("[P] [%3d] %9.3f ms %5.2f%% | %9d %9.3f ms | %s", index, (*it)->second.duration() / 1000.0, - ((f64)(*it)->second.duration() * 100.0) / (f64)total_duration, (*it)->second.count(), - (f64)(*it)->second.duration() / (f64)(*it)->second.count() / 1000.0, (*it)->first.c_str()); + Msg("[P] [%3d] %9.3f ms %5.2f%% %9.3f ms | %9d | %s", index, (*it)->second.duration() / 1000.0, + ((f64)(*it)->second.duration() * 100.0) / (f64)total_duration, + (f64)(*it)->second.duration() / (f64)(*it)->second.count() / 1000.0, (*it)->second.count(), + (*it)->first.c_str()); index += 1; } @@ -217,7 +248,7 @@ void CScriptProfiler::logHookReport() for (auto it = entries.begin(); it != entries.end(); it++) { - if (index >= CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT) + if (index >= entries_limit) break; Msg("[P] [%3d] %9d %5.2f%% | %s", index, (*it)->second.count(), @@ -234,7 +265,7 @@ void CScriptProfiler::logHookReport() FlushLog(); } -void CScriptProfiler::logSamplingReport() +void CScriptProfiler::logSamplingReport(u32 entries_limit) { if (m_sampling_profiling_log.empty()) { @@ -276,7 +307,7 @@ void CScriptProfiler::logSamplingReport() for (auto it = entries.begin(); it != entries.end(); it++) { - if (index >= CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT) + if (index >= entries_limit) break; Msg("[P] [%3d] %9d %5.2f%% | %s", index, (*it)->second.m_samples, @@ -287,7 +318,6 @@ void CScriptProfiler::logSamplingReport() Msg("[P] =================================================================="); Msg("[P] = Total samples: %d", total_count); - Msg("[P] = Total function calls duration: %d ms (approximate)", total_count * m_sampling_profile_interval); Msg("[P] =================================================================="); FlushLog(); @@ -297,13 +327,13 @@ void CScriptProfiler::saveReport() { switch (m_profiler_type) { - case CScriptProfilerType::Hook: - return saveHookReport(); - case CScriptProfilerType::Sampling: - return saveSamplingReport(); - default: - Msg("[P] No active profiling data to save report"); - return; + case CScriptProfilerType::Hook: + return saveHookReport(); + case CScriptProfilerType::Sampling: + return saveSamplingReport(); + default: + Msg("[P] No active profiling data to save report"); + return; } } diff --git a/src/xrScriptEngine/script_profiler.hpp b/src/xrScriptEngine/script_profiler.hpp index c2b80176ac1..d6f3d73679d 100644 --- a/src/xrScriptEngine/script_profiler.hpp +++ b/src/xrScriptEngine/script_profiler.hpp @@ -18,25 +18,27 @@ class XRSCRIPTENGINE_API CScriptProfiler { // todo: Can we make some global module to store all the arguments as experessions? public: - // List of commnad line args for startup profuler attach: + // List of commnad line args for startup profiler attach: constexpr static cpcstr ARGUMENT_PROFILER_DEFAULT = "-lua_profiler"; constexpr static cpcstr ARGUMENT_PROFILER_HOOK = "-lua_hook_profiler"; constexpr static cpcstr ARGUMENT_PROFILER_SAMPLING = "-lua_sampling_profiler"; - static const u32 PROFILE_ENTRIES_LOG_LIMIT = 128; - static const u32 PROFILE_SAMPLING_INTERVAL_DEFAULT = 1; + static const CScriptProfilerType PROFILE_TYPE_DEFAULT = CScriptProfilerType::Hook; + static const u32 PROFILE_ENTRIES_LOG_LIMIT_DEFAULT = 128; + static const u32 PROFILE_SAMPLING_INTERVAL_DEFAULT = 10; static const u32 PROFILE_SAMPLING_INTERVAL_MAX = 1000; private: CScriptEngine* m_engine; CScriptProfilerType m_profiler_type; bool m_active; + + xr_unordered_map m_hook_profiling_portions; + xr_vector m_sampling_profiling_log; /* * Sampling interval for JIT based profiler. * Value should be set in ms and defaults to 10ms. */ - xr_unordered_map m_hook_profiling_portions; - xr_vector m_sampling_profiling_log; u32 m_sampling_profile_interval; public: @@ -44,14 +46,18 @@ class XRSCRIPTENGINE_API CScriptProfiler virtual ~CScriptProfiler(); bool isActive() const { return m_active; }; - void start(CScriptProfilerType profiler_type = CScriptProfilerType::Hook); - void startSamplingMode(u32 sampling_interval); + CScriptProfilerType getType() const { return m_profiler_type; }; + shared_str getTypeString() const; + u32 getRecordsCount() const; + + void start(CScriptProfilerType profiler_type = PROFILE_TYPE_DEFAULT); void startHookMode(); + void startSamplingMode(u32 sampling_interval); void stop(); void reset(); - void logReport(); - void logHookReport(); - void logSamplingReport(); + void logReport(u32 entries_limit = PROFILE_ENTRIES_LOG_LIMIT_DEFAULT); + void logHookReport(u32 entries_limit = PROFILE_ENTRIES_LOG_LIMIT_DEFAULT); + void logSamplingReport(u32 entries_limit = PROFILE_ENTRIES_LOG_LIMIT_DEFAULT); void saveReport(); void saveHookReport(); void saveSamplingReport(); From 3011943ae48341161d9f2f29d559b21daacdaca3 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Sat, 18 Jan 2025 23:17:43 +0200 Subject: [PATCH 17/24] Post-review fixes. Code comments. Adjusted profiling methods to simplify logics flow. Configurable report saving methods. lua_profiler_status console command. --- src/xrGame/console_commands.cpp | 42 ++++-- src/xrScriptEngine/script_engine.hpp | 12 +- src/xrScriptEngine/script_profiler.cpp | 201 +++++++++++++++++++------ src/xrScriptEngine/script_profiler.hpp | 7 +- 4 files changed, 188 insertions(+), 74 deletions(-) diff --git a/src/xrGame/console_commands.cpp b/src/xrGame/console_commands.cpp index 8f11bdac353..1c9de055147 100644 --- a/src/xrGame/console_commands.cpp +++ b/src/xrGame/console_commands.cpp @@ -1998,43 +1998,47 @@ class CCC_LuaProfiler : public IConsole_Command CCC_LuaProfiler(LPCSTR N) : IConsole_Command(N) { bEmptyArgsHandled = true; }; virtual void Execute(LPCSTR args) { - - if (strstr(cName, "lua_profiler_start_hook_mode") == cName) + CScriptProfiler* profiler = GEnv.ScriptEngine->m_profiler; + + if (strstr(cName, "lua_profiler_status") == cName) + { + Msg("[P] Profiler status: %s, type - %s", profiler->isActive() ? "on" : "off", + profiler->getTypeString().c_str()); + } + else if (strstr(cName, "lua_profiler_start_hook_mode") == cName) { - GEnv.ScriptEngine->m_profiler->startHookMode(); + profiler->startHookMode(); } else if (strstr(cName, "lua_profiler_start_sampling_mode") == cName) { u32 interval = atoi(args); - GEnv.ScriptEngine->m_profiler->startSamplingMode( - interval ? interval : CScriptProfiler::PROFILE_SAMPLING_INTERVAL_DEFAULT); + profiler->startSamplingMode(interval ? interval : CScriptProfiler::PROFILE_SAMPLING_INTERVAL_DEFAULT); } else if (strstr(cName, "lua_profiler_start") == cName) { u32 profiler_type = atoi(args); - GEnv.ScriptEngine->m_profiler->start( + profiler->start( (profiler_type ? (CScriptProfilerType)profiler_type : CScriptProfiler::PROFILE_TYPE_DEFAULT)); } else if (strstr(cName, "lua_profiler_stop") == cName) { - GEnv.ScriptEngine->m_profiler->stop(); + profiler->stop(); } else if (strstr(cName, "lua_profiler_reset") == cName) { - GEnv.ScriptEngine->m_profiler->reset(); + profiler->reset(); } else if (strstr(cName, "lua_profiler_log") == cName) { u32 limit = atoi(args); - GEnv.ScriptEngine->m_profiler->logReport( - limit ? limit : CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT_DEFAULT); + profiler->logReport(limit ? limit : CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT_DEFAULT); } else if (strstr(cName, "lua_profiler_save") == cName) { - GEnv.ScriptEngine->m_profiler->saveReport(); + profiler->saveReport(); } }; @@ -2043,8 +2047,11 @@ class CCC_LuaProfiler : public IConsole_Command CScriptProfiler* profiler = GEnv.ScriptEngine->m_profiler; TStatus status_buffer; - - if (strstr(cName, "lua_profiler_start_hook_mode") == cName) + if (strstr(cName, "lua_profiler_status") == cName) + { + // No arguments. + } + else if (strstr(cName, "lua_profiler_start_hook_mode") == cName) { // No arguments. } @@ -2084,10 +2091,14 @@ class CCC_LuaProfiler : public IConsole_Command void Info(TInfo& I) override { - if (strstr(cName, "lua_profiler_start_hook_mode") == cName) + if (strstr(cName, "lua_profiler_status") == cName) + xr_strcpy(I, "no arguments : print lua profiler status"); + else if (strstr(cName, "lua_profiler_start_hook_mode") == cName) xr_strcpy(I, "no arguments : start lua script profiling in hook mode"); else if (strstr(cName, "lua_profiler_start_sampling_mode") == cName) - xr_strcpy(I, "integer value in range [1,1000] : start lua script profiling in sampling mode with provided sampling interval"); + xr_strcpy(I, + "integer value in range [1,1000] : start lua script profiling in sampling mode with provided sampling " + "interval"); else if (strstr(cName, "lua_profiler_start") == cName) xr_strcpy(I, "integer value in range [0,2] : start lua script profiling in provided mode"); else if (strstr(cName, "lua_profiler_stop") == cName) @@ -2185,6 +2196,7 @@ void CCC_RegisterCommands() CMD3(CCC_Mask, "lua_debug", &g_LuaDebug, 1); #endif // MASTER_GOLD + CMD1(CCC_LuaProfiler, "lua_profiler_status"); CMD1(CCC_LuaProfiler, "lua_profiler_start"); CMD1(CCC_LuaProfiler, "lua_profiler_start_sampling_mode"); CMD1(CCC_LuaProfiler, "lua_profiler_start_hook_mode"); diff --git a/src/xrScriptEngine/script_engine.hpp b/src/xrScriptEngine/script_engine.hpp index cd8a12fa86a..c0150567b1c 100644 --- a/src/xrScriptEngine/script_engine.hpp +++ b/src/xrScriptEngine/script_engine.hpp @@ -1,9 +1,9 @@ //////////////////////////////////////////////////////////////////////////// -// Module : script_engine.h -// Created : 01.04.2004 -// Modified : 01.04.2004 -// Author : Dmitriy Iassenev -// Description : XRay Script Engine +// Module : script_engine.h +// Created : 01.04.2004 +// Modified : 01.04.2004 +// Author : Dmitriy Iassenev +// Description : XRay Script Engine //////////////////////////////////////////////////////////////////////////// #pragma once @@ -72,7 +72,7 @@ class XRSCRIPTENGINE_API CScriptEngine { public: constexpr static cpcstr ARGUMENT_ENGINE_NOJIT = "-nojit"; - typedef AssociativeVector CScriptProcessStorage; + typedef AssociativeVector CScriptProcessStorage; static const char* const GlobalNamespace; private: diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index 01145fa757d..16fe59a5273 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -24,6 +24,9 @@ CScriptProfiler::~CScriptProfiler() m_engine = nullptr; } +/* + * @returns current hook type as shared string + */ shared_str CScriptProfiler::getTypeString() const { switch (m_profiler_type) @@ -34,10 +37,15 @@ shared_str CScriptProfiler::getTypeString() const return "Hook"; case CScriptProfilerType::Sampling: return "Sampling"; - default: NODEFAULT; + default: + NODEFAULT; + return "Unknown"; } }; +/* + * @returns count of recorded profiling entries (based on currently active hook type) + */ u32 CScriptProfiler::getRecordsCount() const { switch (m_profiler_type) @@ -48,10 +56,17 @@ u32 CScriptProfiler::getRecordsCount() const return m_hook_profiling_portions.size(); case CScriptProfilerType::Sampling: return m_sampling_profiling_log.size(); - default: NODEFAULT; + default: + NODEFAULT; + return 0; } }; +/* + * Start profiler with provided type. + * + * @param profiler_type - type of the profiler to start + */ void CScriptProfiler::start(CScriptProfilerType profiler_type) { switch (profiler_type) @@ -71,6 +86,9 @@ void CScriptProfiler::start(CScriptProfilerType profiler_type) } } +/* + * Start profiler in hook mode (based on built-in lua tools). + */ void CScriptProfiler::startHookMode() { if (m_active) @@ -79,29 +97,31 @@ void CScriptProfiler::startHookMode() return; } - if (!lua()) + if (lua()) { - Msg("[P] Activating hook profiler on lua engine start, waiting init"); - - m_profiler_type = CScriptProfilerType::Hook; - m_active = true; - - return; + if (attachLuaHook()) + Msg("[P] Starting scripts hook profiler"); + else + { + Msg("[P] Cannot start scripts hook profiler, hook was not set properly"); + return; + } } - - if (!attachLuaHook()) + else { - Msg("[P] Cannot start scripts hook profiler, hook was not set properly"); - return; + Msg("[P] Activating hook profiler on lua engine start, waiting init"); } - Msg("[P] Starting scripts hook profiler"); - m_hook_profiling_portions.clear(); m_profiler_type = CScriptProfilerType::Hook; m_active = true; } +/* + * Start profiler in sampling mode (based on luaJIT built-in profiler). + * + * @param sampling_interval - interval for calls sampling and further reporting + */ void CScriptProfiler::startSamplingMode(u32 sampling_interval) { if (m_active) @@ -110,33 +130,35 @@ void CScriptProfiler::startSamplingMode(u32 sampling_interval) return; } - if (!luaIsJitProfilerDefined(lua())) + if (!luaIsJitProfilerDefined()) { Msg("[P] Cannot start scripts sampling profiler, jit module is not defined"); return; } - if (!lua()) - { - Msg("[P] Activating sampling profiler on lua engine start, waiting init"); - - m_profiler_type = CScriptProfilerType::Sampling; - m_active = true; - - return; - } - clamp(sampling_interval, 1u, PROFILE_SAMPLING_INTERVAL_MAX); - Msg("[P] Starting scripts sampling profiler, interval: %d", sampling_interval); - - luaJitSamplingProfilerAttach(this, sampling_interval); + if (lua()) + { + Msg("[P] Starting scripts sampling profiler, interval: %d", sampling_interval); + luaJitSamplingProfilerAttach(this, sampling_interval); + } + else + Msg("[P] Activating sampling profiler on lua engine start, waiting init"); + m_sampling_profiling_log.clear(); m_sampling_profile_interval = sampling_interval; m_profiler_type = CScriptProfilerType::Sampling; m_active = true; } +/* + * Stop profiler and clean up stored data. + * Clean up attached hooks/jit profilers. + * + * Note: + * - LUA hook is not detached because we cannot be sure where it was attached, but calls are ignore while profiling stopped + */ void CScriptProfiler::stop() { if (!m_active) @@ -168,6 +190,10 @@ void CScriptProfiler::stop() m_sampling_profiling_log.clear(); } +/* + * Reset profiling data. + * Does not affect profiler flow (start, stop, reinit etc). + */ void CScriptProfiler::reset() { Msg("[P] Reset profiler"); @@ -176,6 +202,11 @@ void CScriptProfiler::reset() m_sampling_profiling_log.clear(); } +/* + * Log profiler report with brief summary based on current context. + * + * @param entries_limit - count of top entries to log + */ void CScriptProfiler::logReport(u32 entries_limit) { switch (m_profiler_type) @@ -190,6 +221,11 @@ void CScriptProfiler::logReport(u32 entries_limit) } } +/* + * Log hook profiler report with brief summary. + * + * @param entries_limit - count of top entries to log + */ void CScriptProfiler::logHookReport(u32 entries_limit) { if (m_hook_profiling_portions.empty()) @@ -265,6 +301,11 @@ void CScriptProfiler::logHookReport(u32 entries_limit) FlushLog(); } +/* + * Log sampling profiler report with brief summary. + * + * @param entries_limit - count of top entries to log + */ void CScriptProfiler::logSamplingReport(u32 entries_limit) { if (m_sampling_profiling_log.empty()) @@ -323,21 +364,30 @@ void CScriptProfiler::logSamplingReport(u32 entries_limit) FlushLog(); } +/* + * Save reported data for hook profiler based on current context. + */ void CScriptProfiler::saveReport() { switch (m_profiler_type) { case CScriptProfilerType::Hook: - return saveHookReport(); + return saveHookReport(getHookReportFilename()); case CScriptProfilerType::Sampling: - return saveSamplingReport(); + return saveSamplingReport(getSamplingReportFilename()); default: Msg("[P] No active profiling data to save report"); return; } } -void CScriptProfiler::saveHookReport() +/* + * Save reported data for hook profiler. + * Saved data is represented by lines with serialized stack, calls count and duration. + * + * @param filename - target file to write report to + */ +void CScriptProfiler::saveHookReport(shared_str filename) { if (m_hook_profiling_portions.empty()) { @@ -345,10 +395,8 @@ void CScriptProfiler::saveHookReport() return; } - shared_str log_file_name = getHookReportFilename(); - IWriter* F = FS.w_open(log_file_name.c_str()); - - Msg("[P] Saving hook report to %s", log_file_name.c_str()); + Msg("[P] Saving hook report to %s", filename.c_str()); + IWriter* F = FS.w_open(filename.c_str()); xr_vector entries; entries.reserve(m_hook_profiling_portions.size()); @@ -374,7 +422,13 @@ void CScriptProfiler::saveHookReport() } } -void CScriptProfiler::saveSamplingReport() +/* + * Save reported data for sampling profiler. + * Saved data is represented by lines with folded stacks and count of samples. + * + * @param filename - target file to write report to + */ +void CScriptProfiler::saveSamplingReport(shared_str filename) { if (m_sampling_profiling_log.empty()) { @@ -382,10 +436,8 @@ void CScriptProfiler::saveSamplingReport() return; } - shared_str log_file_name = getSamplingReportFilename(); - IWriter* F = FS.w_open(log_file_name.c_str()); - - Msg("[P] Saving sampling report to %s", log_file_name.c_str()); + Msg("[P] Saving sampling report to %s", filename.c_str()); + IWriter* F = FS.w_open(filename.c_str()); if (F) { @@ -396,6 +448,9 @@ void CScriptProfiler::saveSamplingReport() } } +/* + * @returns filename for hook profiler report + */ shared_str CScriptProfiler::getHookReportFilename() { string_path log_file_name; @@ -405,6 +460,9 @@ shared_str CScriptProfiler::getHookReportFilename() return log_file_name; } +/* + * @returns filename for sampling profiler report + */ shared_str CScriptProfiler::getSamplingReportFilename() { string_path log_file_name; @@ -422,47 +480,59 @@ bool CScriptProfiler::attachLuaHook() lua_Hook hook = lua_gethook(lua()); // Do not rewrite active hooks and verify if correct hooks is set. + // Avoid rewriting of hook since something else took hook place, preferrably we want only 1 hook in script engine. if (hook) return hook == CScriptEngine::lua_hook_call; else return lua_sethook(lua(), CScriptEngine::lua_hook_call, LUA_MASKLINE | LUA_MASKCALL | LUA_MASKRET, 0); } +/* + * Handle profiler dispose event. + * Make sure we are cleaning up all the data/links. + * + * @param L - lua VM active on dispose event + */ void CScriptProfiler::onDispose(lua_State* L) { // When handling instance disposal (reinit), stop profiling for VM. // Otherwise you cannot stop profiling because VM pointer will be destroyed and become inaccessible. if (m_active && m_profiler_type == CScriptProfilerType::Sampling) { - Msg("[P] Disposing sampling dependencies"); + Msg("[P] Disposing sampling profiler dependencies"); luaJitProfilerStop(L); } } +/* + * Handle engine reinit event within profiler. + * Required to switch current profiler context from one lua VM to newly initialize lua VM. + * + * @param L - new lua VM to initialize on + */ void CScriptProfiler::onReinit(lua_State* L) { if (!m_active) return; - Msg("[P] Profiler reinit %d", lua()); + Msg("[P] Profiler reinit, VM:%d", lua()); switch (m_profiler_type) { case CScriptProfilerType::Hook: - if (!attachLuaHook()) + if (!attachLuaHook()) { Msg("[P] Cannot start scripts hook profiler on reinit, hook was not set properly"); return; } Msg("[P] Reinit scripts hook profiler"); - m_hook_profiling_portions.clear(); return; case CScriptProfilerType::Sampling: { - if (!luaIsJitProfilerDefined(lua())) + if (!luaIsJitProfilerDefined()) { Msg("[P] Cannot start scripts sampling profiler on reinit, jit.profiler module is not defined"); return; @@ -470,6 +540,7 @@ void CScriptProfiler::onReinit(lua_State* L) Msg("[P] Re-init scripts sampling profiler - attach handler, interval: %d", m_sampling_profile_interval); luaJitSamplingProfilerAttach(this, m_sampling_profile_interval); + m_sampling_profiling_log.clear(); return; } @@ -478,6 +549,13 @@ void CScriptProfiler::onReinit(lua_State* L) } } +/* + * Callback to handle lua profiling hook. + * Receiving lua events and collecting data in profiler instance to do further performance measurements and assumptions. + * + * @param L - lua VM context of calls + * @param dbg - lua debug context of hook call (only event data is valid) + */ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) { if (!m_active || m_profiler_type != CScriptProfilerType::Hook || dbg->event == LUA_HOOKLINE) @@ -543,6 +621,9 @@ void CScriptProfiler::onLuaHookCall(lua_State* L, lua_Debug* dbg) } } +/* + * @returns reference to currently active lua VM state (or null if it was not initialize yet) + */ lua_State* CScriptProfiler::lua() const { return this->m_engine->lua(); @@ -559,7 +640,7 @@ int CScriptProfiler::luaMemoryUsed(lua_State* L) /* * @returns whether jit is enabled */ -bool CScriptProfiler::luaIsJitProfilerDefined(lua_State* L) +bool CScriptProfiler::luaIsJitProfilerDefined() { // Safest and least invasive way to check it. // Other methods affect lua stack and may add interfere with VS extensions / other hooks / error callbacks. @@ -567,9 +648,11 @@ bool CScriptProfiler::luaIsJitProfilerDefined(lua_State* L) return !strstr(Core.Params, CScriptEngine::ARGUMENT_ENGINE_NOJIT); } -/** -* Attach sampling profiling hooks. -* With provided period report samples and store information in profiler for further reporting. +/* + * Attach sampling profiling hooks. + * With provided period report samples and store information in profiler for further reporting. + * + * @param interval - sampling interval for built-in luaJIT profiler */ void CScriptProfiler::luaJitSamplingProfilerAttach(CScriptProfiler* profiler, u32 interval) { @@ -601,6 +684,8 @@ void CScriptProfiler::luaJitSamplingProfilerAttach(CScriptProfiler* profiler, u3 * Note: The actual sampling precision is OS-dependent. * * @param mode - jit profiling mode variant + * @param callback - callback to handle periodic sampling report event + * @param data - any pointer to receive in sampling report callback to return feedback * @returns whether jit profiler start call was successful */ void CScriptProfiler::luaJitProfilerStart(lua_State* L, cpcstr mode, luaJIT_profile_callback callback, void* data) @@ -610,6 +695,15 @@ void CScriptProfiler::luaJitProfilerStart(lua_State* L, cpcstr mode, luaJIT_prof luaJIT_profile_start(L, mode, callback, data); } +/* + * Stop JIT built-in sampling profiler. + * + * Notes: + * - failsafe, can stop already stopped data + * - profiler is singleton instance across all lua VM states + * - cannot stop profiler with VM reference, if it was started with another instance + * - no status / possibility to check if stop was successful without modifying luaJIT + */ void CScriptProfiler::luaJitProfilerStop(lua_State* L) { luaJIT_profile_stop(L); @@ -623,6 +717,8 @@ void CScriptProfiler::luaJitProfilerStop(lua_State* L) * l — dump module:line * Z — zap trailing separator * i — Sampling interval in milliseconds (default 10ms) + * + * @returns jit profiler dump as shared string */ shared_str CScriptProfiler::luaJitProfilerDumpToString(lua_State* L, cpcstr format, int depth) { @@ -645,6 +741,8 @@ shared_str CScriptProfiler::luaJitProfilerDumpToString(lua_State* L, cpcstr form * l — dump module:line * Z — zap trailing separator * i — Sampling interval in milliseconds (default 10ms) + * + * @returns pair with dump char buffer and length of valid dump data in it */ std::pair CScriptProfiler::luaJitProfilerDump(lua_State* L, cpcstr format, int depth) { @@ -654,6 +752,9 @@ std::pair CScriptProfiler::luaJitProfilerDump(lua_State* L, cpcs return std::make_pair(dump, length); } +/* + * @returns pair with debug information and status of debug information (whether was able to get info from stack) + */ std::pair CScriptProfiler::luaDebugStackInfo(lua_State* L, int level, cpcstr what) { lua_Debug info; diff --git a/src/xrScriptEngine/script_profiler.hpp b/src/xrScriptEngine/script_profiler.hpp index d6f3d73679d..d3321f11c8c 100644 --- a/src/xrScriptEngine/script_profiler.hpp +++ b/src/xrScriptEngine/script_profiler.hpp @@ -59,8 +59,8 @@ class XRSCRIPTENGINE_API CScriptProfiler void logHookReport(u32 entries_limit = PROFILE_ENTRIES_LOG_LIMIT_DEFAULT); void logSamplingReport(u32 entries_limit = PROFILE_ENTRIES_LOG_LIMIT_DEFAULT); void saveReport(); - void saveHookReport(); - void saveSamplingReport(); + void saveHookReport(shared_str filename); + void saveSamplingReport(shared_str filename); shared_str getHookReportFilename(); shared_str getSamplingReportFilename(); @@ -71,8 +71,9 @@ class XRSCRIPTENGINE_API CScriptProfiler private: lua_State* lua() const; + static int luaMemoryUsed(lua_State* L); - static bool luaIsJitProfilerDefined(lua_State* L); + static bool luaIsJitProfilerDefined(); static void luaJitSamplingProfilerAttach(CScriptProfiler* profiler, u32 interval); static void luaJitProfilerStart(lua_State* L, cpcstr mode, luaJIT_profile_callback callback, void* data); static void luaJitProfilerStop(lua_State* L); From 35106323ac3ef0000a3a736d5f9dcc0858c91ba8 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Sat, 18 Jan 2025 23:41:57 +0200 Subject: [PATCH 18/24] Reset type on profiler stop. Respect cases with 0 total duration. Use const expressions for lua profiler commands. --- src/xrGame/console_commands.cpp | 73 +++++++++++++++----------- src/xrScriptEngine/script_profiler.cpp | 14 +++-- 2 files changed, 51 insertions(+), 36 deletions(-) diff --git a/src/xrGame/console_commands.cpp b/src/xrGame/console_commands.cpp index 1c9de055147..199dc431f52 100644 --- a/src/xrGame/console_commands.cpp +++ b/src/xrGame/console_commands.cpp @@ -1995,48 +1995,57 @@ class CCC_UI_Time_Factor : public IConsole_Command class CCC_LuaProfiler : public IConsole_Command { public: + constexpr static cpcstr COMMAND_LUA_PROFILER_STATUS = "lua_profiler_status"; + constexpr static cpcstr COMMAND_LUA_PROFILER_START = "lua_profiler_start"; + constexpr static cpcstr COMMAND_LUA_PROFILER_START_HOOK_MODE = "lua_profiler_start_hook_mode"; + constexpr static cpcstr COMMAND_LUA_PROFILER_START_SAMPLING_MODE = "lua_profiler_start_sampling_mode"; + constexpr static cpcstr COMMAND_LUA_PROFILER_STOP = "lua_profiler_stop"; + constexpr static cpcstr COMMAND_LUA_PROFILER_RESET = "lua_profiler_reset"; + constexpr static cpcstr COMMAND_LUA_PROFILER_LOG = "lua_profiler_log"; + constexpr static cpcstr COMMAND_LUA_PROFILER_SAVE = "lua_profiler_save"; + CCC_LuaProfiler(LPCSTR N) : IConsole_Command(N) { bEmptyArgsHandled = true; }; virtual void Execute(LPCSTR args) { CScriptProfiler* profiler = GEnv.ScriptEngine->m_profiler; - if (strstr(cName, "lua_profiler_status") == cName) + if (strstr(cName, COMMAND_LUA_PROFILER_STATUS) == cName) { Msg("[P] Profiler status: %s, type - %s", profiler->isActive() ? "on" : "off", profiler->getTypeString().c_str()); } - else if (strstr(cName, "lua_profiler_start_hook_mode") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_START_HOOK_MODE) == cName) { profiler->startHookMode(); } - else if (strstr(cName, "lua_profiler_start_sampling_mode") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_START_SAMPLING_MODE) == cName) { u32 interval = atoi(args); profiler->startSamplingMode(interval ? interval : CScriptProfiler::PROFILE_SAMPLING_INTERVAL_DEFAULT); } - else if (strstr(cName, "lua_profiler_start") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_START) == cName) { u32 profiler_type = atoi(args); profiler->start( (profiler_type ? (CScriptProfilerType)profiler_type : CScriptProfiler::PROFILE_TYPE_DEFAULT)); } - else if (strstr(cName, "lua_profiler_stop") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_STOP) == cName) { profiler->stop(); } - else if (strstr(cName, "lua_profiler_reset") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_RESET) == cName) { profiler->reset(); } - else if (strstr(cName, "lua_profiler_log") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_LOG) == cName) { u32 limit = atoi(args); profiler->logReport(limit ? limit : CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT_DEFAULT); } - else if (strstr(cName, "lua_profiler_save") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_SAVE) == cName) { profiler->saveReport(); } @@ -2047,21 +2056,21 @@ class CCC_LuaProfiler : public IConsole_Command CScriptProfiler* profiler = GEnv.ScriptEngine->m_profiler; TStatus status_buffer; - if (strstr(cName, "lua_profiler_status") == cName) + if (strstr(cName, COMMAND_LUA_PROFILER_STATUS) == cName) { // No arguments. } - else if (strstr(cName, "lua_profiler_start_hook_mode") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_START_HOOK_MODE) == cName) { // No arguments. } - else if (strstr(cName, "lua_profiler_start_sampling_mode") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_START_SAMPLING_MODE) == cName) { xr_sprintf(status_buffer, "%d (default) [1-%d] - sampling interval", CScriptProfiler::PROFILE_SAMPLING_INTERVAL_DEFAULT, CScriptProfiler::PROFILE_SAMPLING_INTERVAL_MAX); tips.push_back(status_buffer); } - else if (strstr(cName, "lua_profiler_start") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_START) == cName) { xr_sprintf(status_buffer, "%d - hooks based profiler", CScriptProfilerType::Hook); tips.push_back(status_buffer); @@ -2069,21 +2078,21 @@ class CCC_LuaProfiler : public IConsole_Command xr_sprintf(status_buffer, "%d - sampling based profiler", CScriptProfilerType::Sampling); tips.push_back(status_buffer); } - else if (strstr(cName, "lua_profiler_stop") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_STOP) == cName) { // No arguments. } - else if (strstr(cName, "lua_profiler_reset") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_RESET) == cName) { // No arguments. } - else if (strstr(cName, "lua_profiler_log") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_LOG) == cName) { xr_sprintf(status_buffer, "%d (default) - count of profiling entries to print", CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT_DEFAULT, CScriptProfiler::PROFILE_SAMPLING_INTERVAL_MAX); tips.push_back(status_buffer); } - else if (strstr(cName, "lua_profiler_save") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_SAVE) == cName) { // No arguments. } @@ -2091,23 +2100,23 @@ class CCC_LuaProfiler : public IConsole_Command void Info(TInfo& I) override { - if (strstr(cName, "lua_profiler_status") == cName) + if (strstr(cName, COMMAND_LUA_PROFILER_STATUS) == cName) xr_strcpy(I, "no arguments : print lua profiler status"); - else if (strstr(cName, "lua_profiler_start_hook_mode") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_START_HOOK_MODE) == cName) xr_strcpy(I, "no arguments : start lua script profiling in hook mode"); - else if (strstr(cName, "lua_profiler_start_sampling_mode") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_START_SAMPLING_MODE) == cName) xr_strcpy(I, "integer value in range [1,1000] : start lua script profiling in sampling mode with provided sampling " "interval"); - else if (strstr(cName, "lua_profiler_start") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_START) == cName) xr_strcpy(I, "integer value in range [0,2] : start lua script profiling in provided mode"); - else if (strstr(cName, "lua_profiler_stop") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_STOP) == cName) xr_strcpy(I, "no arguments : stop lua script profiling"); - else if (strstr(cName, "lua_profiler_reset") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_RESET) == cName) xr_strcpy(I, "no arguments : reset lua script profiling stats"); - else if (strstr(cName, "lua_profiler_log") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_LOG) == cName) xr_strcpy(I, "integer value : log lua script profiling stats, limit entries with argument"); - else if (strstr(cName, "lua_profiler_save") == cName) + else if (strstr(cName, COMMAND_LUA_PROFILER_SAVE) == cName) xr_strcpy(I, "no arguments : save lua script profiling stats in a file"); } }; @@ -2196,14 +2205,14 @@ void CCC_RegisterCommands() CMD3(CCC_Mask, "lua_debug", &g_LuaDebug, 1); #endif // MASTER_GOLD - CMD1(CCC_LuaProfiler, "lua_profiler_status"); - CMD1(CCC_LuaProfiler, "lua_profiler_start"); - CMD1(CCC_LuaProfiler, "lua_profiler_start_sampling_mode"); - CMD1(CCC_LuaProfiler, "lua_profiler_start_hook_mode"); - CMD1(CCC_LuaProfiler, "lua_profiler_stop"); - CMD1(CCC_LuaProfiler, "lua_profiler_reset"); - CMD1(CCC_LuaProfiler, "lua_profiler_log"); - CMD1(CCC_LuaProfiler, "lua_profiler_save"); + CMD1(CCC_LuaProfiler, CCC_LuaProfiler::COMMAND_LUA_PROFILER_STATUS); + CMD1(CCC_LuaProfiler, CCC_LuaProfiler::COMMAND_LUA_PROFILER_START); + CMD1(CCC_LuaProfiler, CCC_LuaProfiler::COMMAND_LUA_PROFILER_START_SAMPLING_MODE); + CMD1(CCC_LuaProfiler, CCC_LuaProfiler::COMMAND_LUA_PROFILER_START_HOOK_MODE); + CMD1(CCC_LuaProfiler, CCC_LuaProfiler::COMMAND_LUA_PROFILER_STOP); + CMD1(CCC_LuaProfiler, CCC_LuaProfiler::COMMAND_LUA_PROFILER_RESET); + CMD1(CCC_LuaProfiler, CCC_LuaProfiler::COMMAND_LUA_PROFILER_LOG); + CMD1(CCC_LuaProfiler, CCC_LuaProfiler::COMMAND_LUA_PROFILER_SAVE); #ifdef DEBUG CMD4(CCC_Integer, "lua_gcstep", &psLUA_GCSTEP, 1, 1000); diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index 16fe59a5273..e1bbf27eb67 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -186,6 +186,7 @@ void CScriptProfiler::stop() } m_active = false; + m_profiler_type = CScriptProfilerType::None; m_hook_profiling_portions.clear(); m_sampling_profiling_log.clear(); } @@ -264,10 +265,15 @@ void CScriptProfiler::logHookReport(u32 entries_limit) if (index >= entries_limit) break; - Msg("[P] [%3d] %9.3f ms %5.2f%% %9.3f ms | %9d | %s", index, (*it)->second.duration() / 1000.0, - ((f64)(*it)->second.duration() * 100.0) / (f64)total_duration, - (f64)(*it)->second.duration() / (f64)(*it)->second.count() / 1000.0, (*it)->second.count(), - (*it)->first.c_str()); + if (total_duration > 0) + Msg("[P] [%3d] %9.3f ms %5.2f%% %9.3f ms | %9d | %s", index, (*it)->second.duration() / 1000.0, + ((f64)(*it)->second.duration() * 100.0) / (f64)total_duration, + (f64)(*it)->second.duration() / (f64)(*it)->second.count() / 1000.0, (*it)->second.count(), + (*it)->first.c_str()); + else + // Small measurements chunks can result in 10-20 calls with ~0 total duration. + Msg("[P] [%3d] %9.3f ms %5.2f%% %9.3f ms | %9d | %s", index, 0, 0, 0, (*it)->second.count(), + (*it)->first.c_str()); index += 1; } From d115c617d270fa348c68481975ad99e4788ab8d2 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Sat, 18 Jan 2025 23:59:43 +0200 Subject: [PATCH 19/24] Export `PROFILER_TYPE_NONE`. Export `get_type`. Do not reset data on reinit. --- src/xrScriptEngine/ScriptEngineScript.cpp | 13 +++++++++---- src/xrScriptEngine/script_profiler.cpp | 2 -- 2 files changed, 9 insertions(+), 6 deletions(-) diff --git a/src/xrScriptEngine/ScriptEngineScript.cpp b/src/xrScriptEngine/ScriptEngineScript.cpp index fd1055dc89d..62fe16541d0 100644 --- a/src/xrScriptEngine/ScriptEngineScript.cpp +++ b/src/xrScriptEngine/ScriptEngineScript.cpp @@ -140,6 +140,7 @@ SCRIPT_EXPORT(CScriptEngine, (), { using namespace luabind; + globals(luaState) ["PROFILER_TYPE_NONE"] = (u32) CScriptProfilerType::None; globals(luaState) ["PROFILER_TYPE_HOOK"] = (u32) CScriptProfilerType::Hook; globals(luaState) ["PROFILER_TYPE_SAMPLING"] = (u32) CScriptProfilerType::Sampling; @@ -175,18 +176,22 @@ SCRIPT_EXPORT(CScriptEngine, (), { GEnv.ScriptEngine->m_profiler->isActive(); }), - def("start", +[](CScriptProfilerType hook_type = CScriptProfilerType::None) + def("get_type", +[]() { - GEnv.ScriptEngine->m_profiler->start(hook_type); + GEnv.ScriptEngine->m_profiler->getType(); }), - def("start_sampling_mode", +[](u32 sampling_interval = CScriptProfiler::PROFILE_SAMPLING_INTERVAL_DEFAULT) + def("start", +[](CScriptProfilerType hook_type = CScriptProfilerType::None) { - GEnv.ScriptEngine->m_profiler->startSamplingMode(sampling_interval); + GEnv.ScriptEngine->m_profiler->start(hook_type); }), def("start_hook_mode", +[]() { GEnv.ScriptEngine->m_profiler->startHookMode(); }), + def("start_sampling_mode", +[](u32 sampling_interval = CScriptProfiler::PROFILE_SAMPLING_INTERVAL_DEFAULT) + { + GEnv.ScriptEngine->m_profiler->startSamplingMode(sampling_interval); + }), def("stop", +[]() { GEnv.ScriptEngine->m_profiler->stop(); diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index e1bbf27eb67..7c026489b96 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -533,7 +533,6 @@ void CScriptProfiler::onReinit(lua_State* L) } Msg("[P] Reinit scripts hook profiler"); - m_hook_profiling_portions.clear(); return; case CScriptProfilerType::Sampling: @@ -546,7 +545,6 @@ void CScriptProfiler::onReinit(lua_State* L) Msg("[P] Re-init scripts sampling profiler - attach handler, interval: %d", m_sampling_profile_interval); luaJitSamplingProfilerAttach(this, m_sampling_profile_interval); - m_sampling_profiling_log.clear(); return; } From 5fec5978976a67a0820794361b6a97b6ce5f29bb Mon Sep 17 00:00:00 2001 From: Neloreck Date: Sun, 19 Jan 2025 03:28:21 +0200 Subject: [PATCH 20/24] Adjusted exported functions to use separate overloads for start. --- src/xrScriptEngine/ScriptEngineScript.cpp | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-) diff --git a/src/xrScriptEngine/ScriptEngineScript.cpp b/src/xrScriptEngine/ScriptEngineScript.cpp index 62fe16541d0..588ea465aa9 100644 --- a/src/xrScriptEngine/ScriptEngineScript.cpp +++ b/src/xrScriptEngine/ScriptEngineScript.cpp @@ -172,15 +172,19 @@ SCRIPT_EXPORT(CScriptEngine, (), module(luaState, "profiler") [ - def("is_active", +[]() + def("is_active", +[]() -> bool { - GEnv.ScriptEngine->m_profiler->isActive(); + return GEnv.ScriptEngine->m_profiler->isActive(); }), - def("get_type", +[]() + def("get_type", +[]()-> u32 { - GEnv.ScriptEngine->m_profiler->getType(); + return static_cast(GEnv.ScriptEngine->m_profiler->getType()); }), - def("start", +[](CScriptProfilerType hook_type = CScriptProfilerType::None) + def("start", +[]() + { + GEnv.ScriptEngine->m_profiler->start(); + }), + def("start", +[](CScriptProfilerType hook_type) { GEnv.ScriptEngine->m_profiler->start(hook_type); }), From af68a66c03fead33f43bbe863a39e8d38bd17b19 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Sun, 19 Jan 2025 03:37:24 +0200 Subject: [PATCH 21/24] Spacing removed from switch-cases. --- src/xrScriptEngine/script_profiler.cpp | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/xrScriptEngine/script_profiler.cpp b/src/xrScriptEngine/script_profiler.cpp index 7c026489b96..0975deb41ff 100644 --- a/src/xrScriptEngine/script_profiler.cpp +++ b/src/xrScriptEngine/script_profiler.cpp @@ -37,8 +37,8 @@ shared_str CScriptProfiler::getTypeString() const return "Hook"; case CScriptProfilerType::Sampling: return "Sampling"; - default: - NODEFAULT; + default: + NODEFAULT; return "Unknown"; } }; @@ -56,7 +56,7 @@ u32 CScriptProfiler::getRecordsCount() const return m_hook_profiling_portions.size(); case CScriptProfilerType::Sampling: return m_sampling_profiling_log.size(); - default: + default: NODEFAULT; return 0; } From ee953058cf7eb9ccf365c3ad1cc9af9f83813c75 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Mon, 20 Jan 2025 01:01:20 +0200 Subject: [PATCH 22/24] Corrected wrong parameter name in profiler export. --- src/xrScriptEngine/ScriptEngineScript.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/xrScriptEngine/ScriptEngineScript.cpp b/src/xrScriptEngine/ScriptEngineScript.cpp index 588ea465aa9..cb6f783c24b 100644 --- a/src/xrScriptEngine/ScriptEngineScript.cpp +++ b/src/xrScriptEngine/ScriptEngineScript.cpp @@ -184,9 +184,9 @@ SCRIPT_EXPORT(CScriptEngine, (), { GEnv.ScriptEngine->m_profiler->start(); }), - def("start", +[](CScriptProfilerType hook_type) + def("start", +[](CScriptProfilerType profiler_type) { - GEnv.ScriptEngine->m_profiler->start(hook_type); + GEnv.ScriptEngine->m_profiler->start(profiler_type); }), def("start_hook_mode", +[]() { From 5b40a7ae21dbbb6490efa5f9c7001b04fe9c1e46 Mon Sep 17 00:00:00 2001 From: Neloreck Date: Mon, 20 Jan 2025 01:08:18 +0200 Subject: [PATCH 23/24] Exported variant of `log_report` without parameters. --- src/xrScriptEngine/ScriptEngineScript.cpp | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/src/xrScriptEngine/ScriptEngineScript.cpp b/src/xrScriptEngine/ScriptEngineScript.cpp index cb6f783c24b..d0b40239cc4 100644 --- a/src/xrScriptEngine/ScriptEngineScript.cpp +++ b/src/xrScriptEngine/ScriptEngineScript.cpp @@ -204,7 +204,11 @@ SCRIPT_EXPORT(CScriptEngine, (), { GEnv.ScriptEngine->m_profiler->reset(); }), - def("log_report", +[](u32 entries_limit = CScriptProfiler::PROFILE_ENTRIES_LOG_LIMIT_DEFAULT) + def("log_report", +[]() + { + GEnv.ScriptEngine->m_profiler->logReport(); + }), + def("log_report", +[](u32 entries_limit) { GEnv.ScriptEngine->m_profiler->logReport(entries_limit); }), From f0ee67949272713990c155bd0b48b682e4741cbc Mon Sep 17 00:00:00 2001 From: Neloreck Date: Mon, 20 Jan 2025 01:16:24 +0200 Subject: [PATCH 24/24] Export `start_sampling_mode` as variant with and without interval parameter. --- src/xrScriptEngine/ScriptEngineScript.cpp | 4 ++++ src/xrScriptEngine/script_profiler.hpp | 2 +- 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/src/xrScriptEngine/ScriptEngineScript.cpp b/src/xrScriptEngine/ScriptEngineScript.cpp index d0b40239cc4..0d771a72882 100644 --- a/src/xrScriptEngine/ScriptEngineScript.cpp +++ b/src/xrScriptEngine/ScriptEngineScript.cpp @@ -192,6 +192,10 @@ SCRIPT_EXPORT(CScriptEngine, (), { GEnv.ScriptEngine->m_profiler->startHookMode(); }), + def("start_sampling_mode", +[]() + { + GEnv.ScriptEngine->m_profiler->startSamplingMode(); + }), def("start_sampling_mode", +[](u32 sampling_interval = CScriptProfiler::PROFILE_SAMPLING_INTERVAL_DEFAULT) { GEnv.ScriptEngine->m_profiler->startSamplingMode(sampling_interval); diff --git a/src/xrScriptEngine/script_profiler.hpp b/src/xrScriptEngine/script_profiler.hpp index d3321f11c8c..46086938087 100644 --- a/src/xrScriptEngine/script_profiler.hpp +++ b/src/xrScriptEngine/script_profiler.hpp @@ -52,7 +52,7 @@ class XRSCRIPTENGINE_API CScriptProfiler void start(CScriptProfilerType profiler_type = PROFILE_TYPE_DEFAULT); void startHookMode(); - void startSamplingMode(u32 sampling_interval); + void startSamplingMode(u32 sampling_interval = PROFILE_SAMPLING_INTERVAL_DEFAULT); void stop(); void reset(); void logReport(u32 entries_limit = PROFILE_ENTRIES_LOG_LIMIT_DEFAULT);