Stats system by Kondra

* OTS Statistics by kondra

CMakeLists.txt

@@ -54,6 +54,13 @@ endif ()
 
 find_package(Boost 1.66.0 REQUIRED COMPONENTS date_time system iostreams)
 
+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 ()
+
 include_directories(${Boost_INCLUDE_DIRS} ${Crypto++_INCLUDE_DIR} ${LUA_INCLUDE_DIR} ${MYSQL_INCLUDE_DIR} ${PUGIXML_INCLUDE_DIR})
 target_link_libraries(tfs PRIVATE
         Boost::date_time

config.lua.dist

@@ -174,3 +174,11 @@ 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

data/logs/stats/.gitignore

@@ -0,0 +1 @@
+*.log

src/CMakeLists.txt

@@ -60,6 +60,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}/talkaction.cpp
 	${CMAKE_CURRENT_LIST_DIR}/tasks.cpp
 	${CMAKE_CURRENT_LIST_DIR}/teleport.cpp

src/configmanager.cpp

@@ -310,6 +310,9 @@ bool ConfigManager::load()
 	integer[VIP_PREMIUM_LIMIT] = getGlobalNumber(L, "vipPremiumLimit", 100);
 	integer[DEPOT_FREE_LIMIT] = getGlobalNumber(L, "depotFreeLimit", 2000);
 	integer[DEPOT_PREMIUM_LIMIT] = getGlobalNumber(L, "depotPremiumLimit", 10000);
+	integer[STATS_DUMP_INTERVAL] = getGlobalNumber(L, "statsDumpInterval", 30000);
+	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

@@ -138,6 +138,9 @@ class ConfigManager
 			VIP_PREMIUM_LIMIT,
 			DEPOT_FREE_LIMIT,
 			DEPOT_PREMIUM_LIMIT,
+			STATS_DUMP_INTERVAL,
+			STATS_SLOW_LOG_TIME,
+			STATS_VERY_SLOW_LOG_TIME,
 
 			LAST_INTEGER_CONFIG /* this must be the last one */
 		};

src/database.cpp

@@ -21,6 +21,7 @@
 
 #include "configmanager.h"
 #include "database.h"
+#include "stats.h"
 
 #include <mysql/errmsg.h>
 
@@ -100,6 +101,10 @@ bool Database::executeQuery(const std::string& query)
 	// executes the query
 	databaseLock.lock();
 
+	#ifdef STATS_ENABLED
+		std::chrono::high_resolution_clock::time_point time_point = std::chrono::high_resolution_clock::now();
+	#endif
+
 	while (mysql_real_query(handle, query.c_str(), query.length()) != 0) {
 		std::cout << "[Error - mysql_real_query] Query: " << query.substr(0, 256) << std::endl << "Message: " << mysql_error(handle) << std::endl;
 		auto error = mysql_errno(handle);
@@ -111,6 +116,12 @@ bool Database::executeQuery(const std::string& query)
 	}
 
 	MYSQL_RES* m_res = 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();
+		g_stats.addSqlStats(new Stat(ns, query.substr(0, 100), query.substr(0, 256)));
+	#endif
+
 	databaseLock.unlock();
 
 	if (m_res) {
@@ -124,6 +135,10 @@ DBResult_ptr Database::storeQuery(const std::string& query)
 {
 	databaseLock.lock();
 
+	#ifdef STATS_ENABLED
+		std::chrono::high_resolution_clock::time_point time_point = std::chrono::high_resolution_clock::now();
+	#endif
+
 	retry:
 	while (mysql_real_query(handle, query.c_str(), query.length()) != 0) {
 		std::cout << "[Error - mysql_real_query] Query: " << query << std::endl << "Message: " << mysql_error(handle) << std::endl;
@@ -146,6 +161,12 @@ DBResult_ptr Database::storeQuery(const std::string& query)
 		}
 		goto retry;
 	}
+
+	#ifdef STATS_ENABLED
+		uint64_t ns = std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::high_resolution_clock::now() - time_point).count();
+		g_stats.addSqlStats(new Stat(ns, query.substr(0, 100), query.substr(0, 256)));
+	#endif
+
 	databaseLock.unlock();
 
 	// retrieving results of query

src/game.cpp

@@ -136,6 +136,10 @@ void Game::setGameState(GameState_t newState)
 			g_scheduler.stop();
 			g_databaseTasks.stop();
 			g_dispatcher.stop();
+			#ifdef STATS_ENABLED
+				g_stats.stop();
+			#endif
+
 			break;
 		}
 
@@ -3588,6 +3592,10 @@ void Game::checkCreatures(size_t index)
 	}
 
 	cleanup();
+	#ifdef STATS_ENABLED
+		g_stats.playersOnline = getPlayersOnline();
+	#endif
+
 }
 
 void Game::changeSpeed(Creature* creature, int32_t varSpeedDelta)
@@ -4508,6 +4516,9 @@ void Game::shutdown()
 	g_scheduler.shutdown();
 	g_databaseTasks.shutdown();
 	g_dispatcher.shutdown();
+	#ifdef STATS_ENABLED
+		g_stats.shutdown();
+	#endif
 	map.spawns.clear();
 	raids.clear();
 

src/luascript.cpp

@@ -440,6 +440,16 @@ const std::string& LuaScriptInterface::getFileById(int32_t scriptId)
 	return it->second;
 }
 
+const std::string& LuaScriptInterface::getFileByIdForStats(int32_t scriptId)
+{
+	auto it = cacheFiles.find(scriptId);
+	if (it == cacheFiles.end()) {
+		static const std::string& unk = "(Unknown scriptfile)";
+		return unk;
+	}
+	return it->second;
+}
+
 std::string LuaScriptInterface::getStackTrace(lua_State* L, const std::string& error_desc)
 {
 	luaL_traceback(L, L, error_desc.c_str(), 1);
@@ -531,6 +541,15 @@ int LuaScriptInterface::luaErrorHandler(lua_State* L)
 
 bool LuaScriptInterface::callFunction(int params)
 {
+	#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
+
 	bool result = false;
 	int size = lua_gettop(luaState);
 	if (protectedCall(luaState, params, 1) != 0) {
@@ -544,6 +563,11 @@ bool LuaScriptInterface::callFunction(int params)
 		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();
+		g_stats.addLuaStats(new Stat(ns, getFileByIdForStats(scriptId), ""));
+	#endif
+
 	resetScriptEnv();
 	return result;
 }

src/luascript.h

@@ -201,6 +201,7 @@ class LuaScriptInterface
 		int32_t loadFile(const std::string& file, Npc* npc = nullptr);
 
 		const std::string& getFileById(int32_t scriptId);
+		const std::string& getFileByIdForStats(int32_t scriptId);
 		int32_t getEvent(const std::string& eventName);
 		int32_t getEvent();
 		int32_t getMetaEvent(const std::string& globalName, const std::string& eventName);

src/otpch.h

@@ -39,6 +39,7 @@
 #include <thread>
 #include <unordered_map>
 #include <vector>
+#include <fstream>
 
 #include <boost/asio.hpp>
 

src/otserv.cpp

@@ -42,6 +42,7 @@
 DatabaseTasks g_databaseTasks;
 Dispatcher g_dispatcher;
 Scheduler g_scheduler;
+Stats g_stats;
 
 Game g_game;
 ConfigManager g_config;
@@ -85,6 +86,9 @@ int main(int argc, char* argv[])
 
 	g_dispatcher.start();
 	g_scheduler.start();
+	#ifdef STATS_ENABLED
+		g_stats.start();
+	#endif
 
 	g_dispatcher.addTask(createTask(std::bind(mainLoader, argc, argv, &serviceManager)));
 
@@ -98,11 +102,17 @@ int main(int argc, char* argv[])
 		g_scheduler.shutdown();
 		g_databaseTasks.shutdown();
 		g_dispatcher.shutdown();
+		#ifdef STATS_ENABLED
+			g_stats.shutdown();
+		#endif
 	}
 
 	g_scheduler.join();
 	g_databaseTasks.join();
 	g_dispatcher.join();
+	#ifdef STATS_ENABLED
+		g_stats.join();
+	#endif
 	return 0;
 }
 

src/protocolgame.h

@@ -271,13 +271,13 @@ class ProtocolGame final : public Protocol
 
 		// Helpers so we don't need to bind every time
 		template <typename Callable, typename... Args>
-		void addGameTask(Callable&& function, Args&&... args) {
-			g_dispatcher.addTask(createTask(std::bind(std::forward<Callable>(function), &g_game, std::forward<Args>(args)...)));
+		void addGameTaskWithStats(Callable&& function, const std::string& function_str, const std::string& extra_info, Args&&... args) {
+			g_dispatcher.addTask(createTaskWithStats(std::bind(std::forward<Callable>(function), &g_game, std::forward<Args>(args)...), function_str, extra_info));
 		}
 
 		template <typename Callable, typename... Args>
-		void addGameTaskTimed(uint32_t delay, Callable&& function, Args&&... args) {
-			g_dispatcher.addTask(createTask(delay, std::bind(std::forward<Callable>(function), &g_game, std::forward<Args>(args)...)));
+		void addGameTaskTimedWithStats(uint32_t delay, Callable&& function, const std::string& function_str, const std::string& extra_info, Args&&... args) {
+			g_dispatcher.addTask(createTaskWithStats(delay, std::bind(std::forward<Callable>(function), &g_game, std::forward<Args>(args)...), function_str, extra_info));
 		}
 
 		std::unordered_set<uint32_t> knownCreatureSet;

src/scheduler.cpp

@@ -80,7 +80,7 @@ void Scheduler::shutdown()
 	});
 }
 
-SchedulerTask* createSchedulerTask(uint32_t delay, TaskFunc&& f)
+SchedulerTask* createSchedulerTaskWithStats(uint32_t delay, TaskFunc&& f, const std::string& description, const std::string& extraDescription)
 {
-	return new SchedulerTask(delay, std::move(f));
+	return new SchedulerTask(delay, std::move(f), description, extraDescription);
 }

src/scheduler.h

@@ -41,15 +41,16 @@ class SchedulerTask : public Task
 			return delay;
 		}
 	private:
-		SchedulerTask(uint32_t delay, TaskFunc&& f) : Task(std::move(f)), delay(delay) {}
+		SchedulerTask(uint32_t delay, TaskFunc&& f, const std::string& description, const std::string& extraDescription) :
+		Task(std::move(f), description, extraDescription), delay(delay) {}
 
 		uint32_t eventId = 0;
 		uint32_t delay = 0;
 
-		friend SchedulerTask* createSchedulerTask(uint32_t, TaskFunc&&);
+		friend SchedulerTask* createSchedulerTaskWithStats(uint32_t, TaskFunc&&, const std::string&, const std::string&);
 };
 
-SchedulerTask* createSchedulerTask(uint32_t delay, TaskFunc&& f);
+SchedulerTask* createSchedulerTaskWithStats(uint32_t delay, TaskFunc&& f, const std::string& description, const std::string& extraDescription);
 
 class Scheduler : public ThreadHolder<Scheduler>
 {

src/signals.cpp

@@ -169,6 +169,9 @@ void dispatchSignalHandler(int signal)
 			g_scheduler.join();
 			g_databaseTasks.join();
 			g_dispatcher.join();
+			#ifdef STATS_ENABLED
+				g_stats.join();
+			#endif
 			break;
 #endif
 		default: