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

@@ -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

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");

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

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;

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

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 <algorithm>
+#include <cstddef>
+#include <unordered_map>
+#include <string>
+#include <string_view>
+#include <vector>
+
+#include <fmt/format.h>
+
+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<std::string, lua_timer_t> 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("  <Data pending>");
+		return;
+	}
+
+	std::vector<decltype(g_tic_timers)::iterator> 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 = {};
+	}
+}

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*/

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;

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;

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;
 

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