OTS Statistics by kondra for TFS 1.6+

CMakeLists.txt

@@ -97,6 +97,13 @@ if (BUILD_TESTING)
     enable_testing()
 endif()
 
+if (NOT DEFINED DISABLE_STATS OR NOT DISABLE_STATS)
+    message(STATUS "OTS stats enabled. Run 'cmake -DDISABLE_STATS=ON ..' to disable")
+    ADD_DEFINITIONS(-DSTATS_ENABLED)
+else ()
+    message(STATUS "OTS stats disabled. Run 'cmake -DDISABLE_STATS=OFF ..' to enable")
+endif ()
+
 # Option to disable unity builds
 option(ENABLE_UNITY_BUILD "Enable unity build" ON)
 

config.lua.dist

@@ -168,3 +168,19 @@ ownerName = ""
 ownerEmail = ""
 url = "https://otland.net/"
 location = "Sweden"
+
+-- Server Statistics
+-- time in seconds: 30 = 30 seconds, 0 = disabled
+statsDumpInterval = 30
+-- time in milliseconds: 10 = 0.01 sec, 0 = disabled
+statsSlowLogTime = 10
+-- time in milliseconds: 50 = 0.05 sec, 0 = disabled
+statsVerySlowLogTime = 50
+-- normal stats reports all Lua addEvents as '(Unknown scriptfile)'
+-- with this option enabled, it will generate special.log with addEvent CPU usage
+-- it will also generate special_slow/very_slow.log with addEvent stack backtrace
+statsTrackLuaAddEvents = false
+-- statsTrackLuaAddEvents reports all scripts in special.log with name 'LuaAddEvent'
+-- if you want to track CPU usage of individual addEvent scripts, enable this option - IT WILL USE A LOT MORE CPU!
+-- hashID = stack backtrace will be printed in server console, so you must log server output to some file
+statsTrackLuaAddEventsHashes = false

data/cpplinter.lua

@@ -2137,6 +2137,8 @@ configKeys = {
 	MANASHIELD_BREAKABLE = 36,
 	CHECK_DUPLICATE_STORAGE_KEYS = 37,
 	MONSTER_OVERSPAWN = 38,
+	STATS_TRACK_LUA_ADD_EVENTS = 39,
+	STATS_TRACK_LUA_ADD_EVENTS_HASHES = 40,
 
 	-- ConfigKeysString
 	MAP_NAME = 0,
@@ -2203,6 +2205,9 @@ configKeys = {
 	QUEST_TRACKER_PREMIUM_LIMIT = 42,
 	STAMINA_REGEN_MINUTE = 43,
 	STAMINA_REGEN_PREMIUM = 44,
+	STATS_DUMP_INTERVAL = 45,
+	STATS_SLOW_LOG_TIME = 46,
+	STATS_VERY_SLOW_LOG_TIME = 47,
 }
 
 ITEM_TYPE_NONE = 0

src/CMakeLists.txt

@@ -64,6 +64,7 @@ set(tfs_SRC
 	${CMAKE_CURRENT_LIST_DIR}/signals.cpp
 	${CMAKE_CURRENT_LIST_DIR}/spawn.cpp
 	${CMAKE_CURRENT_LIST_DIR}/spells.cpp
+	${CMAKE_CURRENT_LIST_DIR}/stats.cpp
 	${CMAKE_CURRENT_LIST_DIR}/storeinbox.cpp
 	${CMAKE_CURRENT_LIST_DIR}/talkaction.cpp
 	${CMAKE_CURRENT_LIST_DIR}/tasks.cpp
@@ -152,6 +153,7 @@ set(tfs_HDR
 	${CMAKE_CURRENT_LIST_DIR}/spawn.h
 	${CMAKE_CURRENT_LIST_DIR}/spectators.h
 	${CMAKE_CURRENT_LIST_DIR}/spells.h
+	${CMAKE_CURRENT_LIST_DIR}/stats.h
 	${CMAKE_CURRENT_LIST_DIR}/storeinbox.h
 	${CMAKE_CURRENT_LIST_DIR}/talkaction.h
 	${CMAKE_CURRENT_LIST_DIR}/tasks.h

src/configmanager.cpp

@@ -245,6 +245,8 @@ bool ConfigManager::load()
 	boolean[TWO_FACTOR_AUTH] = getGlobalBoolean(L, "enableTwoFactorAuth", true);
 	boolean[CHECK_DUPLICATE_STORAGE_KEYS] = getGlobalBoolean(L, "checkDuplicateStorageKeys", false);
 	boolean[MONSTER_OVERSPAWN] = getGlobalBoolean(L, "monsterOverspawn", false);
+	boolean[STATS_TRACK_LUA_ADD_EVENTS] = getGlobalBoolean(L, "statsTrackLuaAddEvents", false);
+	boolean[STATS_TRACK_LUA_ADD_EVENTS_HASHES] = getGlobalBoolean(L, "statsTrackLuaAddEventsHashes", false);
 
 	string[DEFAULT_PRIORITY] = getGlobalString(L, "defaultPriority", "high");
 	string[SERVER_NAME] = getGlobalString(L, "serverName", "");
@@ -292,6 +294,9 @@ bool ConfigManager::load()
 	integer[QUEST_TRACKER_PREMIUM_LIMIT] = getGlobalNumber(L, "questTrackerPremiumLimit", 15);
 	integer[STAMINA_REGEN_MINUTE] = getGlobalNumber(L, "timeToRegenMinuteStamina", 3 * 60);
 	integer[STAMINA_REGEN_PREMIUM] = getGlobalNumber(L, "timeToRegenMinutePremiumStamina", 6 * 60);
+	integer[STATS_DUMP_INTERVAL] = getGlobalNumber(L, "statsDumpInterval", 30);
+	integer[STATS_SLOW_LOG_TIME] = getGlobalNumber(L, "statsSlowLogTime", 10);
+	integer[STATS_VERY_SLOW_LOG_TIME] = getGlobalNumber(L, "statsVerySlowLogTime", 50);
 
 	expStages = loadXMLStages();
 	if (expStages.empty()) {

src/configmanager.h

@@ -47,6 +47,8 @@ enum boolean_config_t
 	MANASHIELD_BREAKABLE,
 	CHECK_DUPLICATE_STORAGE_KEYS,
 	MONSTER_OVERSPAWN,
+	STATS_TRACK_LUA_ADD_EVENTS,
+	STATS_TRACK_LUA_ADD_EVENTS_HASHES,
 
 	LAST_BOOLEAN_CONFIG /* this must be the last one */
 };
@@ -121,6 +123,9 @@ enum integer_config_t
 	QUEST_TRACKER_PREMIUM_LIMIT,
 	STAMINA_REGEN_MINUTE,
 	STAMINA_REGEN_PREMIUM,
+	STATS_DUMP_INTERVAL,
+	STATS_SLOW_LOG_TIME,
+	STATS_VERY_SLOW_LOG_TIME,
 
 	LAST_INTEGER_CONFIG /* this must be the last one */
 };

src/database.cpp

@@ -6,6 +6,7 @@
 #include "database.h"
 
 #include "configmanager.h"
+#include "stats.h"
 
 #include <mysql/errmsg.h>
 
@@ -49,6 +50,10 @@ static bool isLostConnectionError(const unsigned error)
 
 static bool executeQuery(tfs::detail::Mysql_ptr& handle, std::string_view query, const bool retryIfLostConnection)
 {
+#ifdef STATS_ENABLED
+	std::chrono::high_resolution_clock::time_point time_point = std::chrono::high_resolution_clock::now();
+#endif
+
 	while (mysql_real_query(handle.get(), query.data(), query.length()) != 0) {
 		std::cout << "[Error - mysql_real_query] Query: " << query.substr(0, 256) << std::endl
 		          << "Message: " << mysql_error(handle.get()) << std::endl;
@@ -58,6 +63,15 @@ static bool executeQuery(tfs::detail::Mysql_ptr& handle, std::string_view query,
 		}
 		handle = connectToDatabase(true);
 	}
+
+#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 true;
 }
 

src/game.cpp

@@ -31,6 +31,7 @@
 #include "server.h"
 #include "spectators.h"
 #include "spells.h"
+#include "stats.h"
 #include "storeinbox.h"
 #include "talkaction.h"
 #include "weapons.h"
@@ -117,6 +118,9 @@ void Game::setGameState(GameState_t newState)
 			g_scheduler.stop();
 			g_databaseTasks.stop();
 			g_dispatcher.stop();
+#ifdef STATS_ENABLED
+			g_stats.stop();
+#endif
 			tfs::http::stop();
 			break;
 		}
@@ -3882,6 +3886,10 @@ void Game::checkCreatures(size_t index)
 	}
 
 	cleanup();
+
+#ifdef STATS_ENABLED
+	g_stats.playersOnline = getPlayersOnline();
+#endif
 }
 
 void Game::changeSpeed(Creature* creature, int32_t varSpeedDelta)
@@ -4800,6 +4808,9 @@ void Game::shutdown()
 	g_scheduler.shutdown();
 	g_databaseTasks.shutdown();
 	g_dispatcher.shutdown();
+#ifdef STATS_ENABLED
+	g_stats.shutdown();
+#endif
 	map.spawns.clear();
 
 	cleanup();

src/luascript.cpp

@@ -33,6 +33,7 @@
 #include "script.h"
 #include "spectators.h"
 #include "spells.h"
+#include "stats.h"
 #include "storeinbox.h"
 #include "teleport.h"
 #include "weapons.h"
@@ -489,12 +490,27 @@ bool LuaScriptInterface::reInitState()
 /// Same as lua_pcall, but adds stack trace to error strings in called function.
 int tfs::lua::protectedCall(lua_State* L, int nargs, int nresults)
 {
+#ifdef STATS_ENABLED
+	auto [scriptId, scriptInterface, callbackId, timerEvent] = getScriptEnv()->getEventInfo();
+	std::chrono::high_resolution_clock::time_point time_point = std::chrono::high_resolution_clock::now();
+#endif
+
 	int error_index = lua_gettop(L) - nargs;
 	lua_pushcfunction(L, luaErrorHandler);
 	lua_insert(L, error_index);
 
 	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) {
+		g_stats.addLuaStats(new Stat(ns, scriptInterface->getFileById(scriptId), ""));
+	}
+#endif
+
 	return ret;
 }
 
@@ -633,6 +649,35 @@ const std::string& LuaScriptInterface::getFileById(int32_t scriptId)
 	return it->second;
 }
 
+#ifdef STATS_ENABLED
+const std::string& LuaScriptInterface::getAddEventStackTracebackHash(const std::string& addEventStackBacktrace)
+{
+	if (!getBoolean(ConfigManager::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
+
 void tfs::lua::reportError(std::string_view function, std::string_view error_desc, lua_State* L /*= nullptr*/,
                            bool stack_trace /*= false*/)
 {
@@ -696,6 +741,9 @@ bool LuaScriptInterface::closeState()
 	}
 
 	cacheFiles.clear();
+#ifdef STATS_ENABLED
+	addEventStackTracebackHashCache.clear();
+#endif
 	if (eventTableRef != -1) {
 		luaL_unref(L, LUA_REGISTRYINDEX, eventTableRef);
 		eventTableRef = -1;
@@ -2285,6 +2333,8 @@ void LuaScriptInterface::registerFunctions()
 	registerEnumIn(L, "configKeys", ConfigManager::SERVER_SAVE_SHUTDOWN);
 	registerEnumIn(L, "configKeys", ConfigManager::ONLINE_OFFLINE_CHARLIST);
 	registerEnumIn(L, "configKeys", ConfigManager::CHECK_DUPLICATE_STORAGE_KEYS);
+	registerEnumIn(L, "configKeys", ConfigManager::STATS_TRACK_LUA_ADD_EVENTS);
+	registerEnumIn(L, "configKeys", ConfigManager::STATS_TRACK_LUA_ADD_EVENTS_HASHES);
 
 	registerEnumIn(L, "configKeys", ConfigManager::MAP_NAME);
 	registerEnumIn(L, "configKeys", ConfigManager::HOUSE_RENT_PERIOD);
@@ -2342,6 +2392,9 @@ void LuaScriptInterface::registerFunctions()
 	registerEnumIn(L, "configKeys", ConfigManager::STAMINA_REGEN_PREMIUM);
 	registerEnumIn(L, "configKeys", ConfigManager::HOUSE_DOOR_SHOW_PRICE);
 	registerEnumIn(L, "configKeys", ConfigManager::MONSTER_OVERSPAWN);
+	registerEnumIn(L, "configKeys", ConfigManager::STATS_DUMP_INTERVAL);
+	registerEnumIn(L, "configKeys", ConfigManager::STATS_SLOW_LOG_TIME);
+	registerEnumIn(L, "configKeys", ConfigManager::STATS_VERY_SLOW_LOG_TIME);
 
 	registerEnumIn(L, "configKeys", ConfigManager::QUEST_TRACKER_FREE_LIMIT);
 	registerEnumIn(L, "configKeys", ConfigManager::QUEST_TRACKER_PREMIUM_LIMIT);
@@ -3983,6 +4036,14 @@ int LuaScriptInterface::luaAddEvent(lua_State* L)
 	eventDesc.function = luaL_ref(L, LUA_REGISTRYINDEX);
 	eventDesc.scriptId = tfs::lua::getScriptEnv()->getScriptId();
 
+#ifdef STATS_ENABLED
+	if (getBoolean(ConfigManager::STATS_TRACK_LUA_ADD_EVENTS)) {
+		std::string trackLuaAddEventLog = getStackTrace(L, "");
+		replaceString(trackLuaAddEventLog, "\n", " ");
+		eventDesc.stackTraceback = trackLuaAddEventLog;
+	}
+#endif
+
 	auto& lastTimerEventId = g_luaEnvironment.lastEventTimerId;
 	eventDesc.eventId = g_scheduler.addEvent(
 	    createSchedulerTask(delay, [=]() { g_luaEnvironment.executeTimerEvent(lastTimerEventId); }));
@@ -18707,6 +18768,9 @@ bool LuaEnvironment::closeState()
 	areaIdMap.clear();
 	timerEvents.clear();
 	cacheFiles.clear();
+#ifdef STATS_ENABLED
+	addEventStackTracebackHashCache.clear();
+#endif
 
 	lua_close(L);
 	L = nullptr;
@@ -18808,10 +18872,23 @@ void LuaEnvironment::executeTimerEvent(uint32_t eventIndex)
 
 	// call the function
 	if (tfs::lua::reserveScriptEnv()) {
+#ifdef STATS_ENABLED
+		std::chrono::high_resolution_clock::time_point time_point = std::chrono::high_resolution_clock::now();
+#endif
 		ScriptEnvironment* env = tfs::lua::getScriptEnv();
 		env->setTimerEvent();
 		env->setScriptId(timerEventDesc.scriptId, this);
 		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 (getBoolean(ConfigManager::STATS_TRACK_LUA_ADD_EVENTS)) {
+			g_stats.addSpecialStats(new Stat(ns, getAddEventStackTracebackHash(timerEventDesc.stackTraceback),
+			                                 timerEventDesc.stackTraceback));
+		}
+#endif
 	} else {
 		std::cout << "[Error - LuaScriptInterface::executeTimerEvent] Call stack overflow\n";
 	}

src/luascript.h

@@ -42,6 +42,9 @@ struct LuaTimerEventDesc
 	int32_t function = -1;
 	std::vector<int32_t> parameters;
 	uint32_t eventId = 0;
+#ifdef STATS_ENABLED
+	std::string stackTraceback;
+#endif
 
 	LuaTimerEventDesc() = default;
 	LuaTimerEventDesc(LuaTimerEventDesc&& other) = default;
@@ -133,6 +136,9 @@ class LuaScriptInterface
 	int32_t loadFile(const std::string& file, Npc* npc = nullptr);
 
 	const std::string& getFileById(int32_t scriptId);
+#ifdef STATS_ENABLED
+	const std::string& getAddEventStackTracebackHash(const std::string& addEventStackBacktrace);
+#endif
 	int32_t getEvent(std::string_view eventName);
 	int32_t getEvent();
 	int32_t getMetaEvent(const std::string& globalName, const std::string& eventName);
@@ -166,6 +172,9 @@ class LuaScriptInterface
 
 	// script file cache
 	std::map<int32_t, std::string> cacheFiles;
+#ifdef STATS_ENABLED
+	std::map<std::string, std::string> addEventStackTracebackHashCache;
+#endif
 
 private:
 	// lua functions