feat: Ots stats

cmake/modules/CrystalLib.cmake

@@ -52,6 +52,14 @@ else()
     log_option_disabled("Build unity")
 endif()
 
+# === OTS Statistics ===
+if(NOT DEFINED DISABLE_STATS OR NOT DISABLE_STATS)
+    message(STATUS "OTS stats enabled. Run 'cmake -DDISABLE_STATS=1 ..' to disable")
+    add_definitions(-DSTATS_ENABLED)
+else()
+    message(STATUS "OTS stats disabled. Run 'cmake -DDISABLE_STATS=0 ..' to enable")
+endif()
+
 # *****************************************************************************
 # Target include directories - to allow #include
 # *****************************************************************************

config.lua.dist

@@ -714,6 +714,12 @@ metricsPrometheusAddress = "0.0.0.0:9464"
 metricsEnableOstream = false
 metricsOstreamInterval = 1000
 
+-- OTS Statistics
+-- NOTE: time in seconds: 30 = 30 seconds, 0 = disabled
+statsDumpInterval = 30
+statsSlowLogTime = 10
+statsVerySlowLogTime = 50
+
 -- OTC Features
 -- NOTE: Features added in this list will be forced to be used on OTCR
 -- These features can be found in "modules/gamelib/const.lua"

src/config/config_enums.hpp

@@ -373,6 +373,11 @@ enum ConfigKey_t : uint16_t {
 	AMPLIFICATION_CHANCE_FORMULA_A,
 	AMPLIFICATION_CHANCE_FORMULA_B,
 	AMPLIFICATION_CHANCE_FORMULA_C,
+	STATS_TRACK_LUA_ADD_EVENTS,
+	STATS_TRACK_LUA_ADD_EVENTS_HASHES,
+	STATS_DUMP_INTERVAL,
+	STATS_SLOW_LOG_TIME,
+	STATS_VERY_SLOW_LOG_TIME,
 	TOGGLE_GUILDHALL_NEED_GUILD,
 	TOGGLE_MAX_CONNECTIONS_BY_IP,
 	MAX_IP_CONNECTIONS,

src/config/configmanager.cpp

@@ -185,6 +185,8 @@ bool ConfigManager::load() {
 	loadBoolConfig(L, UNLOCK_ALL_FAMILIARS, "unlockAllFamiliars", false);
 	loadBoolConfig(L, LEAVE_PARTY_ON_DEATH, "leavePartyOnDeath", false);
 	loadBoolConfig(L, TOGGLE_SPECIAL_TILES, "toggleSpecialTiles", false);
+	loadBoolConfig(L, STATS_TRACK_LUA_ADD_EVENTS, "statsTrackLuaAddEvents", false);
+	loadBoolConfig(L, STATS_TRACK_LUA_ADD_EVENTS_HASHES, "statsTrackLuaAddEventsHashes", false);
 	loadBoolConfig(L, TOGGLE_GUILDHALL_NEED_GUILD, "toggleGuildHallNeedGuild", true);
 	loadBoolConfig(L, TOGGLE_MAX_CONNECTIONS_BY_IP, "toggleMaxConnectionsByIP", false);
 	loadBoolConfig(L, TOGGLE_GUILD_WARS, "toggleGuildWars", false);
@@ -407,6 +409,9 @@ bool ConfigManager::load() {
 	loadIntConfig(L, MARKET_ACTIONS_DELAY_INTERVAL, "marketActionsDelay", 1000);
 	loadIntConfig(L, IMBUEMENT_ACTIONS_DELAY_INTERVAL, "imbueActionsDelay", 1000);
 	loadIntConfig(L, EXPERIENCE_SHARE_ACTIVITY, "experienceShareActivity", 2 * 60 * 1000);
+	loadIntConfig(L, STATS_DUMP_INTERVAL, "statsDumpInterval", 30000);
+	loadIntConfig(L, STATS_SLOW_LOG_TIME, "statsSlowLogTime", 10);
+	loadIntConfig(L, STATS_VERY_SLOW_LOG_TIME, "statsVerySlowLogTime", 50);
 	loadIntConfig(L, MAX_HOUSES_LIMIT, "maxHousesLimit", 3);
 	loadIntConfig(L, MAX_IP_CONNECTIONS, "maxIPConnections", 4);
 	loadIntConfig(L, STASH_MANAGE_AMOUNT, "stashManageAmount", 100000);

src/crystalserver.cpp

@@ -44,6 +44,7 @@
 #include "server/network/protocol/protocolstatus.hpp"
 #include "server/network/webhook/webhook.hpp"
 #include "creatures/players/vocations/vocation.hpp"
+#include "utils/stats.hpp"
 
 CrystalServer::CrystalServer(
 	Logger &logger,
@@ -91,6 +92,10 @@ int CrystalServer::run() {
 				setWorldType();
 				loadMaps();
 
+#ifdef STATS_ENABLED
+				g_stats().start();
+#endif
+
 				logger.info("Initializing gamestate...");
 				g_game().setGameState(GAME_STATE_INIT);
 
@@ -154,6 +159,10 @@ int CrystalServer::run() {
 
 	serviceManager.run();
 
+#ifdef STATS_ENABLED
+	g_stats().join();
+#endif
+
 	shutdown();
 	return EXIT_SUCCESS;
 }

src/database/database.cpp

@@ -21,6 +21,7 @@
 #include "lib/di/container.hpp"
 #include "lib/metrics/metrics.hpp"
 #include "utils/tools.hpp"
+#include "utils/stats.hpp"
 #include <ctime>
 
 Database::~Database() {
@@ -229,6 +230,11 @@ bool Database::retryQuery(std::string_view query, int retries) {
 }
 
 bool Database::executeQuery(std::string_view query) {
+
+#ifdef STATS_ENABLED
+	std::chrono::high_resolution_clock::time_point time_point = std::chrono::high_resolution_clock::now();
+#endif
+
 	if (!handle) {
 		g_logger().error("Database not initialized!");
 		return false;
@@ -244,6 +250,12 @@ bool Database::executeQuery(std::string_view query) {
 	bool success = retryQuery(query, 10);
 	mysql_free_result(mysql_store_result(handle));
 
+#ifdef STATS_ENABLED
+	uint64_t ns = std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::high_resolution_clock::now() - time_point).count();
+	std::string statsQuery = { query.begin(), query.end() };
+	g_stats().addSqlStats(new Stat(ns, statsQuery.substr(0, 100), statsQuery.substr(0, 256)));
+#endif
+
 	return success;
 }
 

src/game/game.cpp

@@ -76,6 +76,7 @@
 #include "server/network/webhook/webhook.hpp"
 #include "server/server.hpp"
 #include "utils/tools.hpp"
+#include "utils/stats.hpp"
 #include "utils/wildcardtree.hpp"
 #include "creatures/players/vocations/vocation.hpp"
 
@@ -720,6 +721,9 @@ void Game::setGameState(GameState_t newState) {
 
 			g_dispatcher().addEvent([this] { shutdown(); }, __FUNCTION__);
 
+#ifdef STATS_ENABLED
+			g_stats().stop();
+#endif
 			break;
 		}
 
@@ -6997,6 +7001,10 @@ void Game::checkCreatures() {
 	});
 
 	index = (index + 1) % EVENT_CREATURECOUNT;
+
+#ifdef STATS_ENABLED
+	g_stats().playersOnline = getPlayersOnline();
+#endif
 }
 
 void Game::changeSpeed(const std::shared_ptr<Creature> &creature, int32_t varSpeedDelta) {
@@ -8880,6 +8888,10 @@ void Game::shutdown() {
 	map.spawnsNpc.clear();
 	raids.clear();
 
+#ifdef STATS_ENABLED
+	g_stats().shutdown();
+#endif
+
 	if (serviceManager) {
 		serviceManager->stop();
 	}

src/lua/functions/lua_functions_loader.cpp

@@ -33,8 +33,8 @@
 #include "lua/functions/map/map_functions.hpp"
 #include "lua/functions/core/game/zone_functions.hpp"
 #include "lua/global/lua_variant.hpp"
-
 #include "enums/lua_variant_type.hpp"
+#include "utils/stats.hpp"
 
 class LuaScriptInterface;
 
@@ -101,6 +101,16 @@ std::string Lua::getErrorDesc(ErrorCode_t code) {
 }
 
 int Lua::protectedCall(lua_State* L, int nargs, int nresults) {
+#ifdef STATS_ENABLED
+	int32_t scriptId;
+	int32_t callbackId;
+	bool timerEvent;
+	// auto [scriptId, scriptInterface, callbackId, timerEvent] = getScriptEnv()->getEventInfo();
+	LuaScriptInterface* scriptInterface;
+	getScriptEnv()->getEventInfo(scriptId, scriptInterface, callbackId, timerEvent);
+	std::chrono::high_resolution_clock::time_point time_point = std::chrono::high_resolution_clock::now();
+#endif
+
 	if (const int ret = validateDispatcherContext(__FUNCTION__); ret != 0) {
 		return ret;
 	}
@@ -111,6 +121,33 @@ int Lua::protectedCall(lua_State* L, int nargs, int nresults) {
 
 	const int ret = lua_pcall(L, nargs, nresults, error_index);
 	lua_remove(L, error_index);
+
+#ifdef STATS_ENABLED
+	uint64_t ns = std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::high_resolution_clock::now() - time_point).count();
+	if (scriptInterface) {
+		std::string label;
+		if (scriptId == EVENT_ID_LOADING) {
+			label = scriptInterface->getLoadingFile();
+		} else if (scriptId == EVENT_ID_USER) {
+			label = "user";
+		} else if (scriptId == 0) {
+			label = timerEvent ? std::string("LuaAddEvent") : scriptInterface->getInterfaceName();
+		} else {
+			label = scriptInterface->getFileById(scriptId);
+			if (label == "(Unknown scriptfile)") {
+				label = timerEvent ? std::string("LuaAddEvent") : scriptInterface->getInterfaceName();
+			}
+		}
+
+		for (auto &ch : label) {
+			if (ch == '\\') {
+				ch = '/';
+			}
+		}
+		g_stats().addLuaStats(new Stat(ns, label, ""));
+	}
+#endif
+
 	return ret;
 }
 

src/lua/global/lua_timer_event_descr.hpp

@@ -29,6 +29,9 @@ struct LuaTimerEventDesc {
 	int32_t function = -1;
 	std::list<int32_t> parameters;
 	uint32_t eventId = 0;
+#ifdef STATS_ENABLED
+	std::string stackTraceback;
+#endif
 
 	LuaTimerEventDesc() = default;
 	LuaTimerEventDesc(LuaTimerEventDesc &&other) = default;

src/lua/scripts/lua_environment.cpp

@@ -22,6 +22,8 @@
 #include "lua/scripts/script_environment.hpp"
 #include "lua/global/lua_timer_event_descr.hpp"
 #include "lib/di/container.hpp"
+#include "utils/stats.hpp"
+#include "config/configmanager.hpp"
 
 bool LuaEnvironment::shuttingDown = false;
 
@@ -88,6 +90,9 @@ bool LuaEnvironment::closeState() {
 	areaIdMap.clear();
 	timerEvents.clear();
 	cacheFiles.clear();
+#ifdef STATS_ENABLED
+	addEventStackTracebackHashCache.clear();
+#endif
 
 	lua_close(luaState);
 	luaState = nullptr;
@@ -150,10 +155,33 @@ void LuaEnvironment::executeTimerEvent(uint32_t eventIndex) {
 
 	// call the function
 	if (reserveScriptEnv()) {
+#ifdef STATS_ENABLED
+		std::chrono::high_resolution_clock::time_point time_point = std::chrono::high_resolution_clock::now();
+#endif
 		ScriptEnvironment* env = getScriptEnv();
 		env->setTimerEvent();
 		env->setScriptId(timerEventDesc.scriptId, this);
+#ifdef STATS_ENABLED
+		if (g_configManager().getBoolean(STATS_TRACK_LUA_ADD_EVENTS_HASHES)) {
+			env->setEventTag(getAddEventStackTracebackHash(timerEventDesc.stackTraceback));
+		} else {
+			if (!timerEventDesc.scriptName.empty()) {
+				env->setEventTag(timerEventDesc.scriptName);
+			} else {
+				env->setEventTag("LuaAddEvent");
+			}
+		}
+#endif
+
 		callFunction(timerEventDesc.parameters.size());
+
+#ifdef STATS_ENABLED
+		uint64_t ns = std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::high_resolution_clock::now() - time_point).count();
+		if (g_configManager().getBoolean(STATS_TRACK_LUA_ADD_EVENTS)) {
+			g_stats().addSpecialStats(new Stat(ns, getAddEventStackTracebackHash(timerEventDesc.stackTraceback), timerEventDesc.stackTraceback));
+		}
+#endif
+
 	} else {
 		g_logger().error("[LuaEnvironment::executeTimerEvent - Lua file {}] "
 		                 "Call stack overflow. Too many lua script calls being nested",

src/lua/scripts/luascript.cpp

@@ -19,6 +19,7 @@
 
 #include "lua/scripts/lua_environment.hpp"
 #include "lib/metrics/metrics.hpp"
+#include "utils/stats.hpp"
 
 ScriptEnvironment::DBResultMap ScriptEnvironment::tempResults;
 uint32_t ScriptEnvironment::lastResultId = 0;
@@ -159,6 +160,33 @@
 	return runningEventId++;
 }
 
+#ifdef STATS_ENABLED
+const std::string &LuaScriptInterface::getAddEventStackTracebackHash(const std::string &addEventStackBacktrace) {
+	if (!g_configManager().getBoolean(STATS_TRACK_LUA_ADD_EVENTS_HASHES)) {
+		static const std::string &hashesDisabledText = "LuaAddEvent";
+		return hashesDisabledText;
+	}
+
+	if (auto it { addEventStackTracebackHashCache.find(addEventStackBacktrace) };
+	    it != std::end(addEventStackTracebackHashCache)) {
+		return it->second;
+	}
+
+	std::chrono::high_resolution_clock::time_point time_point = std::chrono::high_resolution_clock::now();
+	auto* hash = new std::string(
+		fmt::format("LuaAddEvent-{:d}", adlerChecksum(reinterpret_cast<const uint8_t*>(addEventStackBacktrace.c_str()), addEventStackBacktrace.length()))
+	);
+	uint64_t ns = std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::high_resolution_clock::now() - time_point)
+					  .count();
+
+	addEventStackTracebackHashCache[addEventStackBacktrace] = *hash;
+
+	std::cout << "Generated new addEvent hash (" << ns << "): " << *hash << "=" << addEventStackBacktrace << std::endl;
+
+	return *hash;
+}
+#endif
+
 const std::string &LuaScriptInterface::getFileById(int32_t scriptId) {
 	if (scriptId == EVENT_ID_LOADING) {
 		return loadingFile;
@@ -234,6 +262,11 @@
 	}
 
 	cacheFiles.clear();
+
+#ifdef STATS_ENABLED
+	addEventStackTracebackHashCache.clear();
+#endif
+
 	if (eventTableRef != -1) {
 		luaL_unref(luaState, LUA_REGISTRYINDEX, eventTableRef);
 		eventTableRef = -1;
@@ -275,6 +308,15 @@
 }
 
 bool LuaScriptInterface::callFunction(int params) const {
+#ifdef STATS_ENABLED
+	int32_t scriptId;
+	int32_t callbackId;
+	bool timerEvent;
+	LuaScriptInterface* scriptInterface;
+	getScriptEnv()->getEventInfo(scriptId, scriptInterface, callbackId, timerEvent);
+	std::chrono::high_resolution_clock::time_point time_point = std::chrono::high_resolution_clock::now();
+#endif
+
 	metrics::lua_latency measure(getMetricsScope());
 	bool result = false;
 	const int size = lua_gettop(luaState);
@@ -289,6 +331,31 @@
 		LuaScriptInterface::reportError(nullptr, "Stack size changed!");
 	}
 
+#ifdef STATS_ENABLED
+	uint64_t ns = std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::high_resolution_clock::now() - time_point).count();
+	std::string label;
+	if (scriptId == EVENT_ID_LOADING) {
+		label = getLoadingFile();
+	} else if (scriptId == EVENT_ID_USER) {
+		label = "user";
+	} else if (scriptId == 0) {
+		label = timerEvent ? std::string("LuaAddEvent") : getInterfaceName();
+	} else {
+		label = scriptInterface->getFileById(scriptId);
+		if (label == "(Unknown scriptfile)") {
+			label = timerEvent ? std::string("LuaAddEvent") : getInterfaceName();
+		}
+	}
+
+	for (auto &ch : label) {
+		if (ch == '\\') {
+			ch = '/';
+		}
+	}
+
+	g_stats().addLuaStats(new Stat(ns, label, ""));
+#endif
+
 	resetScriptEnv();
 	return result;
 }