From 05d322fa9c79f964f55120c15b0456383ec6b4fb Mon Sep 17 00:00:00 2001 From: Neloreck Date: Tue, 14 Jan 2025 20:08:47 +0200 Subject: [PATCH] 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