From 61709d36a824f638c09d2913b8868fcf6f257abe Mon Sep 17 00:00:00 2001 From: James R Date: Sat, 11 Nov 2023 02:27:39 -0800 Subject: [PATCH] Add basic profiling for Lua hooks (except HUD hooks) - Add lua_profile cheat: calculate average time spent in hooks over a period - Show hook times in a sorted table, along with lump name, script line number and hook type - Show cumulative time spent in game logic hooks and percentage of overhead to game logic --- src/CMakeLists.txt | 1 + src/cvars.cpp | 3 + src/d_clisrv.c | 1 + src/d_main.cpp | 9 ++ src/lua_hooklib.c | 47 ++++++++- src/lua_profile.cpp | 242 ++++++++++++++++++++++++++++++++++++++++++++ src/lua_profile.h | 34 +++++++ src/m_perfstats.c | 1 + src/m_perfstats.h | 1 + src/p_tick.c | 4 + src/typedef.h | 3 + 11 files changed, 345 insertions(+), 1 deletion(-) create mode 100644 src/lua_profile.cpp create mode 100644 src/lua_profile.h diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index 8cfba2d4c..86e82808a 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -115,6 +115,7 @@ add_executable(SRB2SDL2 MACOSX_BUNDLE WIN32 lua_blockmaplib.c lua_hudlib.c lua_hudlib_drawlist.c + lua_profile.cpp k_kart.c k_respawn.c k_collide.cpp diff --git a/src/cvars.cpp b/src/cvars.cpp index 4b0897dcf..feaed0d9a 100644 --- a/src/cvars.cpp +++ b/src/cvars.cpp @@ -854,6 +854,9 @@ consvar_t cv_devmode_screen = PlayerCheat("devmode_screen", "1").min_max(1, 4).d consvar_t cv_drawpickups = PlayerCheat("drawpickups", "Yes").yes_no().description("Hide rings, spheres, item capsules, prison capsules (visual only)"); consvar_t cv_drawinput = PlayerCheat("drawinput", "No").yes_no().description("Draw turn inputs outside of Record Attack (turn solver debugging)"); +void lua_profile_OnChange(void); +consvar_t cv_lua_profile = PlayerCheat("lua_profile", "0").values(CV_Unsigned).onchange(lua_profile_OnChange).description("Show hook timings over an average of N tics"); + void CV_palette_OnChange(void); consvar_t cv_palette = PlayerCheat("palette", "").onchange_noinit(CV_palette_OnChange).description("Force palette to a different lump"); consvar_t cv_palettenum = PlayerCheat("palettenum", "0").values(CV_Unsigned).onchange_noinit(CV_palette_OnChange).description("Use a different sub-palette by default"); diff --git a/src/d_clisrv.c b/src/d_clisrv.c index 2bfc47f24..60a76c341 100644 --- a/src/d_clisrv.c +++ b/src/d_clisrv.c @@ -6142,6 +6142,7 @@ boolean TryRunTics(tic_t realtics) DEBFILE(va("============ Running tic %d (local %d)\n", gametic, localgametic)); + ps_prevtictime = ps_tictime; ps_tictime = I_GetPreciseTime(); dontRun = ExtraDataTicker(); diff --git a/src/d_main.cpp b/src/d_main.cpp index bfcd0fc96..3c7e51d83 100644 --- a/src/d_main.cpp +++ b/src/d_main.cpp @@ -96,6 +96,10 @@ #include "lua_script.h" +#include "lua_profile.h" + +extern "C" consvar_t cv_lua_profile; + /* Manually defined asset hashes * Last updated 2019 / 01 / 18 - Kart v1.0.2 - Main assets * Last updated 2020 / 08 / 30 - Kart v1.3 - patch.kart @@ -765,6 +769,11 @@ static bool D_Display(void) M_DrawPerfStats(); } + if (cv_lua_profile.value > 0) + { + LUA_RenderTimers(); + } + ps_swaptime = I_GetPreciseTime(); I_FinishUpdate(); // page flip or blit buffer ps_swaptime = I_GetPreciseTime() - ps_swaptime; diff --git a/src/lua_hooklib.c b/src/lua_hooklib.c index 873b6d332..f73578a81 100644 --- a/src/lua_hooklib.c +++ b/src/lua_hooklib.c @@ -22,7 +22,9 @@ #include "lua_libs.h" #include "lua_hook.h" #include "lua_hud.h" // hud_running errors +#include "lua_profile.h" +#include "command.h" #include "m_perfstats.h" #include "d_netcmd.h" // for cv_perfstats #include "i_system.h" // I_GetPreciseTime @@ -402,9 +404,52 @@ static void get_hook_from_table(Hook_State *hook, int n) lua_getref(gL, hookRefs[hook->id]); } +static int pcall(Hook_State *hook) +{ + return lua_pcall(gL, hook->values, hook->results, EINDEX); +} + +static const char *hook_name(Hook_State *hook) +{ + if (hud_running) + { + return hudHookNames[hook->hook_type]; + } + else if (hook->string) + { + return stringHookNames[hook->hook_type]; + } + else if (hook->mobj_type > 0) + { + return mobjHookNames[hook->hook_type]; + } + else + { + return hookNames[hook->hook_type]; + } +} + +static int pcall_timed_or_untimed(Hook_State *hook) +{ + extern consvar_t cv_lua_profile; + + if (!hud_running && cv_lua_profile.value > 0) + { + lua_timer_t *timer = LUA_BeginFunctionTimer(gL, -1 - hook->values, hook_name(hook)); + int k = pcall(hook); + LUA_EndFunctionTimer(timer); + + return k; + } + else + { + return pcall(hook); + } +} + static int call_single_hook_no_copy(Hook_State *hook) { - if (lua_pcall(gL, hook->values, hook->results, EINDEX) == 0) + if (pcall_timed_or_untimed(hook) == 0) { if (hook->results > 0) { diff --git a/src/lua_profile.cpp b/src/lua_profile.cpp new file mode 100644 index 000000000..ee2a15ed0 --- /dev/null +++ b/src/lua_profile.cpp @@ -0,0 +1,242 @@ +// DR. ROBOTNIK'S RING RACERS +//----------------------------------------------------------------------------- +// Copyright (C) 2023 by James Robert Roman +// +// This program is free software distributed under the +// terms of the GNU General Public License, version 2. +// See the 'LICENSE' file for more details. +//----------------------------------------------------------------------------- + +#include +#include +#include +#include +#include +#include + +#include + +extern "C" { +#include "blua/lua.h" +}; + +#include "v_draw.hpp" + +#include "command.h" +#include "doomtype.h" +#include "i_system.h" +#include "lua_profile.h" +#include "m_perfstats.h" + +extern "C" consvar_t cv_lua_profile; + +namespace +{ + +precise_t g_time_reference; +int g_tics_counted; + +double g_running_tic_time; +double g_avg_tic_time; + +bool g_invalid; + +}; // namespace + +struct lua_timer_t +{ + struct Stat + { + double calls = 0; + double time = 0.0; + }; + + Stat running, avg; +}; + +namespace +{ + +std::unordered_map g_tic_timers; + +}; // namespace + +lua_timer_t* LUA_BeginFunctionTimer(lua_State* L, int fn_idx, const char* name) +{ + lua_Debug ar; + + lua_pushvalue(L, fn_idx); + lua_getinfo(L, ">S", &ar); + + auto label = [&] + { + using sv = std::string_view; + sv view{ar.source}; + + switch (view.front()) + { + case '@': // file + if (std::size_t p = view.rfind('/'); p != sv::npos) // lump or base + { + return view.substr(p + 1); + } + break; + + case '=': // ?? + view.remove_prefix(1); + break; + } + + return view; + }; + + auto [it, ins] = g_tic_timers.try_emplace(fmt::format("{}:{} ({})", label(), ar.linedefined, name)); + auto& [key, timer] = *it; + + g_time_reference = I_GetPreciseTime(); + + return &timer; +} + +void LUA_EndFunctionTimer(lua_timer_t* timer) +{ + precise_t t = I_GetPreciseTime() - g_time_reference; + double precision = I_GetPrecisePrecision(); + + timer->running.time += t / precision; + timer->running.calls += 1.0; +} + +void LUA_ResetTicTimers(void) +{ + if (cv_lua_profile.value <= 0) + { + return; + } + + if (g_tics_counted < cv_lua_profile.value) + { + g_tics_counted++; + + double precision = I_GetPrecisePrecision(); + g_running_tic_time += ps_prevtictime / precision; + } + else + { + double counted = g_tics_counted; + + for (auto& [key, timer] : g_tic_timers) + { + timer.avg = {timer.running.calls / counted, timer.running.time / counted}; + timer.running = {}; + } + + g_avg_tic_time = g_running_tic_time / counted; + g_running_tic_time = 0.0; + + g_tics_counted = 1; + + g_invalid = false; + } +} + +void LUA_RenderTimers(void) +{ + using srb2::Draw; + + constexpr int kRowHeight = 4; + + Draw row = Draw(0, kRowHeight).font(Draw::Font::kConsole).align(Draw::Align::kLeft).scale(0.5).flags(V_MONOSPACE); + row.y(-kRowHeight).text("-- AVERAGES PER TIC (over {} tics) --", cv_lua_profile.value); + + if (g_invalid) + { + row.flags(V_GRAYMAP).text(" "); + return; + } + + std::vector view; + view.reserve(g_tic_timers.size()); + + auto color_flag = [](double t) + { + if (t < 10.0) + { + return V_GRAYMAP; + } + else if (t >= 100.0) + { + return V_YELLOWMAP; + } + else + { + return 0; + } + }; + + { + double cum = 0.0; + + for (auto it = g_tic_timers.begin(); it != g_tic_timers.end(); ++it) + { + auto& [key, timer] = *it; + + cum += timer.avg.time; + + if (timer.avg.time > 0.0) + { + view.push_back(it); + } + } + + Draw tally = row.flags(color_flag(cum * 1'000'000.0)); + + tally.text("{:8.2f} us - TOTAL", cum * 1'000'000.0); + tally.y(kRowHeight).text("{:8.2f} ms", cum * 1000.0); + tally.y(kRowHeight * 2).text( + "{:8.2f}% overhead ({:.2f} / {:.2f}) <-- not counting rendering time", + (cum / g_avg_tic_time) * 100.0, + cum * TICRATE, + g_avg_tic_time * TICRATE + ); + + row = row.y(kRowHeight * 4); + } + + std::sort( + view.rbegin(), + view.rend(), + [](auto a, auto b) + { + auto& [k1, t1] = *a; + auto& [k2, t2] = *b; + return t1.avg.time < t2.avg.time; + } + ); + + for (auto it : view) + { + auto& [key, timer] = *it; + + double t = timer.avg.time * 1'000'000.0; + + row.flags(color_flag(t)).text( + "{:>8.2f} us {:>8.2f} calls - {}", + t, + timer.avg.calls, + key + ); + + row = row.y(kRowHeight); + } +} + +extern "C" void lua_profile_OnChange(void) +{ + g_invalid = true; + + if (cv_lua_profile.value == 0) + { + g_tic_timers = {}; + } +} diff --git a/src/lua_profile.h b/src/lua_profile.h new file mode 100644 index 000000000..cd772509c --- /dev/null +++ b/src/lua_profile.h @@ -0,0 +1,34 @@ +// DR. ROBOTNIK'S RING RACERS +//----------------------------------------------------------------------------- +// Copyright (C) 2023 by James Robert Roman +// +// This program is free software distributed under the +// terms of the GNU General Public License, version 2. +// See the 'LICENSE' file for more details. +//----------------------------------------------------------------------------- + +#ifndef lua_profile_h +#define lua_profile_h + +#include "blua/lua.h" +#include "doomtype.h" +#include "typedef.h" + +#ifdef __cplusplus +extern "C" { +#endif + +struct lua_timer_t; + +void LUA_ResetTicTimers(void); + +lua_timer_t *LUA_BeginFunctionTimer(lua_State *L, int fn_idx, const char *name); +void LUA_EndFunctionTimer(lua_timer_t *timer); + +void LUA_RenderTimers(void); + +#ifdef __cplusplus +} // extern "C" +#endif + +#endif/*lua_profile_h*/ diff --git a/src/m_perfstats.c b/src/m_perfstats.c index 37697052c..81de6f527 100644 --- a/src/m_perfstats.c +++ b/src/m_perfstats.c @@ -46,6 +46,7 @@ struct perfstatrow { static precise_t ps_frametime = 0; precise_t ps_tictime = 0; +precise_t ps_prevtictime = 0; precise_t ps_playerthink_time = 0; precise_t ps_botticcmd_time = 0; diff --git a/src/m_perfstats.h b/src/m_perfstats.h index f95776e1a..bfc995f55 100644 --- a/src/m_perfstats.h +++ b/src/m_perfstats.h @@ -30,6 +30,7 @@ typedef enum } ps_types_t; extern precise_t ps_tictime; +extern precise_t ps_prevtictime; extern precise_t ps_playerthink_time; extern precise_t ps_botticcmd_time; diff --git a/src/p_tick.c b/src/p_tick.c index 0023d2a2c..8743a2bc6 100644 --- a/src/p_tick.c +++ b/src/p_tick.c @@ -46,6 +46,8 @@ #include "music.h" #include "k_dialogue.h" +#include "lua_profile.h" + #ifdef PARANOIA #include "deh_tables.h" // MOBJTYPE_LIST #endif @@ -831,6 +833,8 @@ void P_Ticker(boolean run) G_ReadDemoTiccmd(&players[i].cmd, i); } + LUA_ResetTicTimers(); + ps_lua_mobjhooks = 0; ps_checkposition_calls = 0; diff --git a/src/typedef.h b/src/typedef.h index 248acc03b..b32d4b974 100644 --- a/src/typedef.h +++ b/src/typedef.h @@ -247,6 +247,9 @@ TYPEDEF (mapUserProperties_t); // lua_hudlib_drawlist.h typedef struct huddrawlist_s *huddrawlist_h; +// lua_profile.h +TYPEDEF (lua_timer_t); + // m_aatree.h TYPEDEF (aatree_t);