Base implementation of profiler to improve / work on.

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(

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)
+    ];
 });

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<CDbgScriptThreads>(scriptEngine, this);
+    m_callStack = xr_new<CScriptCallStack>(this);
+    m_lua = xr_new<CDbgLuaHelper>(this);
     ZeroMemory(m_curr_connected_mslot, sizeof(m_curr_connected_mslot));
     //	m_pDebugger					= this;
     m_nLevel = 0;

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<CScriptProfiler>();
 }
 
 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));
 }
 

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)
     {

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<decltype(m_profiling_portions)::iterator> 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