diff --git a/CMakeLists.txt b/CMakeLists.txt index 7d6a539325..b0564f93b3 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -63,6 +63,13 @@ endif () find_package(Boost 1.66.0 REQUIRED COMPONENTS date_time system filesystem 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 diff --git a/config.lua.dist b/config.lua.dist index 2870da2237..1b40210978 100644 --- a/config.lua.dist +++ b/config.lua.dist @@ -165,3 +165,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 diff --git a/data/logs/stats/.gitignore b/data/logs/stats/.gitignore new file mode 100644 index 0000000000..bf0824e596 --- /dev/null +++ b/data/logs/stats/.gitignore @@ -0,0 +1 @@ +*.log \ No newline at end of file diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index a9544050dd..de84e1f194 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -63,6 +63,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 diff --git a/src/configmanager.cpp b/src/configmanager.cpp index fdc9195b71..700d35baf0 100644 --- a/src/configmanager.cpp +++ b/src/configmanager.cpp @@ -274,6 +274,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()) { diff --git a/src/configmanager.h b/src/configmanager.h index 89c8c3b6b9..01b23e96cc 100644 --- a/src/configmanager.h +++ b/src/configmanager.h @@ -118,6 +118,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 */ }; diff --git a/src/database.cpp b/src/database.cpp index e5f3f03d40..23da7fb680 100644 --- a/src/database.cpp +++ b/src/database.cpp @@ -5,6 +5,7 @@ #include "configmanager.h" #include "database.h" +#include "stats.h" #include @@ -84,6 +85,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); @@ -95,6 +100,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::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) { @@ -108,6 +119,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; @@ -130,6 +145,12 @@ DBResult_ptr Database::storeQuery(const std::string& query) } goto retry; } + +#ifdef STATS_ENABLED + uint64_t ns = std::chrono::duration_cast(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 diff --git a/src/game.cpp b/src/game.cpp index ef17fccbc4..cf1a60937b 100644 --- a/src/game.cpp +++ b/src/game.cpp @@ -136,6 +136,9 @@ void Game::setGameState(GameState_t newState) g_scheduler.stop(); g_databaseTasks.stop(); g_dispatcher.stop(); +#ifdef STATS_ENABLED + g_stats.stop(); +#endif break; } @@ -3739,6 +3742,10 @@ void Game::checkCreatures(size_t index) } cleanup(); + +#ifdef STATS_ENABLED + g_stats.playersOnline = getPlayersOnline(); +#endif } void Game::changeSpeed(Creature* creature, int32_t varSpeedDelta) @@ -4621,6 +4628,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(); diff --git a/src/luascript.cpp b/src/luascript.cpp index f46b1a808d..24e1a2d2ec 100644 --- a/src/luascript.cpp +++ b/src/luascript.cpp @@ -423,6 +423,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) { lua_getglobal(L, "debug"); @@ -528,6 +538,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) { @@ -541,6 +560,11 @@ bool LuaScriptInterface::callFunction(int params) LuaScriptInterface::reportError(nullptr, "Stack size changed!"); } +#ifdef STATS_ENABLED + uint64_t ns = std::chrono::duration_cast(std::chrono::high_resolution_clock::now() - time_point).count(); + g_stats.addLuaStats(new Stat(ns, getFileByIdForStats(scriptId), "")); +#endif + resetScriptEnv(); return result; } diff --git a/src/luascript.h b/src/luascript.h index fea060bf9d..50356cc78a 100644 --- a/src/luascript.h +++ b/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); diff --git a/src/otserv.cpp b/src/otserv.cpp index 4cbda33dc1..acf6fcfc29 100644 --- a/src/otserv.cpp +++ b/src/otserv.cpp @@ -28,6 +28,7 @@ DatabaseTasks g_databaseTasks; Dispatcher g_dispatcher; Scheduler g_scheduler; +Stats g_stats; Game g_game; ConfigManager g_config; @@ -71,6 +72,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))); @@ -84,11 +88,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; } diff --git a/src/protocolgame.h b/src/protocolgame.h index ce00dd2966..2d53d10f86 100644 --- a/src/protocolgame.h +++ b/src/protocolgame.h @@ -293,13 +293,13 @@ class ProtocolGame final : public Protocol // Helpers so we don't need to bind every time template - void addGameTask(Callable&& function, Args&&... args) { - g_dispatcher.addTask(createTask(std::bind(std::forward(function), &g_game, std::forward(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(function), &g_game, std::forward(args)...), function_str, extra_info)); } template - void addGameTaskTimed(uint32_t delay, Callable&& function, Args&&... args) { - g_dispatcher.addTask(createTask(delay, std::bind(std::forward(function), &g_game, std::forward(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(function), &g_game, std::forward(args)...), function_str, extra_info)); } std::unordered_set knownCreatureSet; diff --git a/src/scheduler.cpp b/src/scheduler.cpp index ae1fbba816..6e69c8a882 100644 --- a/src/scheduler.cpp +++ b/src/scheduler.cpp @@ -64,7 +64,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); } diff --git a/src/scheduler.h b/src/scheduler.h index a43b33ea17..b64339da80 100644 --- a/src/scheduler.h +++ b/src/scheduler.h @@ -25,15 +25,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 { diff --git a/src/signals.cpp b/src/signals.cpp index bd2f2dc966..e922eaac27 100644 --- a/src/signals.cpp +++ b/src/signals.cpp @@ -159,6 +159,9 @@ void dispatchSignalHandler(int signal) g_scheduler.join(); g_databaseTasks.join(); g_dispatcher.join(); +#ifdef STATS_ENABLED + g_stats.join(); +#endif break; #endif default: diff --git a/src/stats.cpp b/src/stats.cpp new file mode 100644 index 0000000000..b8e3b48c41 --- /dev/null +++ b/src/stats.cpp @@ -0,0 +1,235 @@ +#include + +#include "otpch.h" + +#include "configmanager.h" +#include "stats.h" +#include "tasks.h" +#include "tools.h" + +extern ConfigManager g_config; + +int64_t Stats::DUMP_INTERVAL = 30000; // 30 sec +uint32_t Stats::SLOW_EXECUTION_TIME = 10000000; // 10 ms +uint32_t Stats::VERY_SLOW_EXECUTION_TIME = 50000000; // 50 ms + +AutoStatRecursive* AutoStatRecursive::activeStat = nullptr; + +void Stats::threadMain() { + std::unique_lock taskLockUnique(statsLock, std::defer_lock); + bool last_iteration = false; + lua.lastDump = sql.lastDump = special.lastDump = OTSYS_TIME(); + playersOnline = 0; + for(auto& dispatcher : dispatchers) { + dispatcher.waitTime = 0; + dispatcher.lastDump = OTSYS_TIME(); + } + while(true) { + taskLockUnique.lock(); + + DUMP_INTERVAL = g_config.getNumber(ConfigManager::STATS_DUMP_INTERVAL) * 1000; + SLOW_EXECUTION_TIME = g_config.getNumber(ConfigManager::STATS_SLOW_LOG_TIME) * 1000000; + VERY_SLOW_EXECUTION_TIME = g_config.getNumber(ConfigManager::STATS_VERY_SLOW_LOG_TIME) * 1000000; + + std::vector> tasks; + for (auto &dispatcher : dispatchers) { + tasks.push_back(std::move(dispatcher.queue)); + dispatcher.queue.clear(); + } + std::forward_list < Stat * > lua_stats(std::move(lua.queue)); + lua.queue.clear(); + std::forward_list < Stat * > sql_stats(std::move(sql.queue)); + sql.queue.clear(); + std::forward_list < Stat * > special_stats(std::move(special.queue)); + special.queue.clear(); + taskLockUnique.unlock(); + + parseDispatchersQueue(tasks); + parseLuaQueue(lua_stats); + parseSqlQueue(sql_stats); + parseSpecialQueue(special_stats); + + int threadId = 0; + for (auto &dispatcher : dispatchers) { + if (DUMP_INTERVAL == 0) { + dispatcher.stats.clear(); + dispatcher.waitTime = 0; + dispatcher.lastDump = OTSYS_TIME(); + continue; + } + if (dispatcher.lastDump + DUMP_INTERVAL < OTSYS_TIME() || last_iteration) { + std::stringstream ss; + float execution_time = 0; + for (auto &it : dispatcher.stats) + execution_time += it.second.executionTime; + ss << "Thread: " << ++threadId << " Cpu usage: " << (execution_time / 10000.) / ((float) DUMP_INTERVAL) << "%" << + " Idle: " << (dispatcher.waitTime / 10000.) / ((float) DUMP_INTERVAL) << "%" << + " Other: " << 100. - (((execution_time + dispatcher.waitTime) / 10000.) / ((float) DUMP_INTERVAL)) << "%"; + ss << " Players online: " << playersOnline << "\n"; + if(dispatcher.waitTime > 0) + writeStats("dispatcher.log", dispatcher.stats, ss.str()); + dispatcher.stats.clear(); + dispatcher.waitTime = 0; + dispatcher.lastDump = OTSYS_TIME(); + } + } + if(lua.lastDump + DUMP_INTERVAL < OTSYS_TIME() || last_iteration) { + writeStats("lua.log", lua.stats); + lua.stats.clear(); + lua.lastDump = OTSYS_TIME(); + } + if(sql.lastDump + DUMP_INTERVAL < OTSYS_TIME() || last_iteration) { + writeStats("sql.log", sql.stats); + sql.stats.clear(); + sql.lastDump = OTSYS_TIME(); + } + if(special.lastDump + DUMP_INTERVAL < OTSYS_TIME() || last_iteration) { + writeStats("special.log", special.stats); + special.stats.clear(); + special.lastDump = OTSYS_TIME(); + } + + if(last_iteration) + break; + if(getState() == THREAD_STATE_TERMINATED) { + last_iteration = true; + continue; + } + std::this_thread::sleep_for(std::chrono::milliseconds(100)); + } +} + +void Stats::addDispatcherTask(int index, Task* task) { + std::lock_guard lockClass(statsLock); + dispatchers[index].queue.push_front(task); +} + +void Stats::addLuaStats(Stat* stats) { + std::lock_guard lockClass(statsLock); + lua.queue.push_front(stats); +} + +void Stats::addSqlStats(Stat* stats) { + std::lock_guard lockClass(statsLock); + sql.queue.push_front(stats); +} + +void Stats::addSpecialStats(Stat* stats) { + std::lock_guard lockClass(statsLock); + special.queue.push_front(stats); +} + +void Stats::parseDispatchersQueue(std::vector> queues) { + int i = 0; + for(auto& dispatcher : dispatchers) { + for(Task* task : queues[i++]) { + auto it = dispatcher.stats.emplace(task->description, statsData(0, 0, task->extraDescription)).first; + it->second.calls += 1; + it->second.executionTime += task->executionTime; + if(VERY_SLOW_EXECUTION_TIME > 0 && task->executionTime > VERY_SLOW_EXECUTION_TIME) { + writeSlowInfo("dispatcher_very_slow.log", task->executionTime, task->description, task->extraDescription); + } else if(SLOW_EXECUTION_TIME > 0 && task->executionTime > SLOW_EXECUTION_TIME) { + writeSlowInfo("dispatcher_slow.log", task->executionTime, task->description, task->extraDescription); + } + delete task; + } + } +} + +void Stats::parseLuaQueue(std::forward_list & queue) { + for(Stat* stats : queue) { + auto it = lua.stats.emplace(stats->description, statsData(0, 0, stats->extraDescription)).first; + it->second.calls += 1; + it->second.executionTime += stats->executionTime; + + if(VERY_SLOW_EXECUTION_TIME > 0 && stats->executionTime > VERY_SLOW_EXECUTION_TIME) { + writeSlowInfo("lua_very_slow.log", stats->executionTime, stats->description, stats->extraDescription); + } else if(SLOW_EXECUTION_TIME > 0 && stats->executionTime > SLOW_EXECUTION_TIME) { + writeSlowInfo("lua_slow.log", stats->executionTime, stats->description, stats->extraDescription); + } + delete stats; + } +} + +void Stats::parseSqlQueue(std::forward_list & queue) { + for(Stat* stats : queue) { + auto it = sql.stats.emplace(stats->description, statsData(0, 0, stats->extraDescription)).first; + it->second.calls += 1; + it->second.executionTime += stats->executionTime; + + if(VERY_SLOW_EXECUTION_TIME > 0 && stats->executionTime > VERY_SLOW_EXECUTION_TIME) { + writeSlowInfo("sql_very_slow.log", stats->executionTime, stats->description, stats->extraDescription); + } else if(SLOW_EXECUTION_TIME > 0 && stats->executionTime > SLOW_EXECUTION_TIME) { + writeSlowInfo("sql_slow.log", stats->executionTime, stats->description, stats->extraDescription); + } + delete stats; + } +} + +void Stats::parseSpecialQueue(std::forward_list & queue) { + for(Stat* stats : queue) { + auto it = special.stats.emplace(stats->description, statsData(0, 0, stats->extraDescription)).first; + it->second.calls += 1; + it->second.executionTime += stats->executionTime; + + if(VERY_SLOW_EXECUTION_TIME > 0 && stats->executionTime > VERY_SLOW_EXECUTION_TIME) { + writeSlowInfo("special_very_slow.log", stats->executionTime, stats->description, stats->extraDescription); + } else if(SLOW_EXECUTION_TIME > 0 && stats->executionTime > SLOW_EXECUTION_TIME) { + writeSlowInfo("special_slow.log", stats->executionTime, stats->description, stats->extraDescription); + } + delete stats; + } +} + +void Stats::writeSlowInfo(const std::string& file, uint64_t executionTime, const std::string& description, const std::string& extraDescription) { + std::ofstream out(std::string("data/logs/stats/") + file, std::ofstream::out | std::ofstream::app); + if (!out.is_open()) { + std::clog << "Can't open " << std::string("data/logs/stats/") + file << " (check if directory exists)" << std::endl; + return; + } + out << "[" << formatDate(time(nullptr)) << "] Execution time: " << (executionTime / 1000000) << " ms - " << description << " - " << extraDescription << "\n"; + out.flush(); + out.close(); +} + +void Stats::writeStats(const std::string& file, const statsMap& stats, const std::string& extraInfo) { + if (DUMP_INTERVAL == 0) { + return; + } + + std::ofstream out(std::string("data/logs/stats/") + file, std::ofstream::out | std::ofstream::app); + if (!out.is_open()) { + std::clog << "Can't open " << std::string("data/logs/stats/") + file << " (check if directory exists)" << std::endl; + return; + } + if(stats.empty()) { + out.close(); + return; + } + out << "[" << formatDate(time(nullptr)) << "]\n"; + + std::vector> pairs; + for (auto& it : stats) + pairs.emplace_back(it); + + sort(pairs.begin(), pairs.end(), [=](const std::pair& a, const std::pair& b) { + return a.second.executionTime > b.second.executionTime; + }); + + out << extraInfo; + float total_time = 0; + out << std::setw(10) << "Time (ms)" << std::setw(10) << "Calls" + << std::setw(15) << "Rel usage " << "%" << std::setw(15) << "Real usage " << "%" << " " << "Description" << "\n"; + for(auto& it : pairs) + total_time += it.second.executionTime; + for(auto& it : pairs) { + float percent = 100 * (float)it.second.executionTime / total_time; + float realPercent = (float)it.second.executionTime / ((float)DUMP_INTERVAL * 10000.); + if(percent > 0.1) + out << std::setw(10) << it.second.executionTime / 1000000 << std::setw(10) << it.second.calls + << std::setw(15) << std::setprecision(5) << std::fixed << percent << "%" << std::setw(15) << std::setprecision(5) << std::fixed << realPercent << "%" << " " << it.first << "\n"; + } + out << "\n"; + out.flush(); + out.close(); +} diff --git a/src/stats.h b/src/stats.h new file mode 100644 index 0000000000..696830783f --- /dev/null +++ b/src/stats.h @@ -0,0 +1,125 @@ +#ifndef TFS_STATS_H +#define TFS_STATS_H + +#include +#include + +#include "thread_holder_base.h" + +class Task; + +#ifdef STATS_ENABLED +#define createTask(function) createTaskWithStats(function, #function, __FUNCTION__) +#define createTimedTask(delay, function) createTaskWithStats(delay, function, #function, __FUNCTION__) +#define createSchedulerTask(delay, function) createSchedulerTaskWithStats(delay, function, #function, __FUNCTION__) +#define addGameTask(function, ...) addGameTaskWithStats(function, #function, __FUNCTION__, __VA_ARGS__) +#define addGameTaskTimed(delay, function, ...) addGameTaskTimedWithStats(delay, function, #function, __FUNCTION__, __VA_ARGS__) +#else +#define createTask(function) createTaskWithStats(function, "", "") +#define createTimedTask(delay, function) createTaskWithStats(delay, function, "", "") +#define createSchedulerTask(delay, function) createSchedulerTaskWithStats(delay, function, "", "") +#define addGameTask(function, ...) addGameTaskWithStats(function, "", "", __VA_ARGS__) +#define addGameTaskTimed(delay, function, ...) addGameTaskTimedWithStats(delay, function, "", "", __VA_ARGS__) +#endif + +struct Stat { + Stat(uint64_t _executionTime, const std::string& _description, const std::string& _extraDescription) : + executionTime(_executionTime), description(_description), extraDescription(_extraDescription) {}; + uint64_t executionTime = 0; + std::string description; + std::string extraDescription; +}; + +struct statsData { + statsData(uint32_t _calls, uint64_t _executionTime, const std::string& _extraInfo) : + calls(_calls), executionTime(_executionTime), extraInfo(_extraInfo) {} + uint32_t calls = 0; + uint64_t executionTime = 0; + std::string extraInfo; +}; + +using statsMap = std::map; + +class Stats : public ThreadHolder { +public: + void threadMain(); + void shutdown() { + setState(THREAD_STATE_TERMINATED); + } + + void addDispatcherTask(int index, Task* task); + void addLuaStats(Stat* stats); + void addSqlStats(Stat* stats); + void addSpecialStats(Stat* stats); + std::atomic& dispatcherWaitTime(int index) { + return dispatchers[index].waitTime; + } + + static uint32_t SLOW_EXECUTION_TIME; + static uint32_t VERY_SLOW_EXECUTION_TIME; + static int64_t DUMP_INTERVAL; + + std::atomic playersOnline; + +private: + void parseDispatchersQueue(std::vector> queues); + void parseLuaQueue(std::forward_list & queue); + void parseSqlQueue(std::forward_list & queue); + void parseSpecialQueue(std::forward_list & queue); + static void writeSlowInfo(const std::string& file, uint64_t executionTime, const std::string& description, const std::string& extraDescription); + static void writeStats(const std::string& file, const statsMap& stats, const std::string& extraInfo = ""); + + std::mutex statsLock; + struct { + std::forward_list queue; + statsMap stats; + std::atomic waitTime; + int64_t lastDump; + } dispatchers[3]; + struct { + std::forward_list queue; + statsMap stats; + int64_t lastDump; + } lua, sql, special; +}; + +extern Stats g_stats; + +class AutoStat { +public: + AutoStat(const std::string& description, const std::string& extraDescription = "") : + time_point(std::chrono::high_resolution_clock::now()), stat(new Stat(0, description, extraDescription)) {} + + ~AutoStat() { + stat->executionTime = std::chrono::duration_cast(std::chrono::high_resolution_clock::now() - time_point).count(); + stat->executionTime -= minusTime; + g_stats.addSpecialStats(stat); + } + +protected: + uint64_t minusTime = 0; + std::chrono::high_resolution_clock::time_point time_point; + +private: + Stat* stat; +}; + +class AutoStatRecursive : public AutoStat { +public: + AutoStatRecursive(const std::string& description, const std::string& extraDescription = "") : AutoStat(description, extraDescription) { + parent = activeStat; + activeStat = this; + } + ~AutoStatRecursive() { + assert(activeStat == this); + activeStat = parent; + if(activeStat) + activeStat->minusTime += std::chrono::duration_cast(std::chrono::high_resolution_clock::now() - time_point).count(); + } + +private: + static AutoStatRecursive* activeStat; + AutoStatRecursive* parent; +}; + +#endif diff --git a/src/tasks.cpp b/src/tasks.cpp index f10daf15c7..979d6f470b 100644 --- a/src/tasks.cpp +++ b/src/tasks.cpp @@ -8,14 +8,14 @@ extern Game g_game; -Task* createTask(TaskFunc&& f) +Task* createTaskWithStats(TaskFunc&& f, const std::string& description, const std::string& extraDescription) { - return new Task(std::move(f)); + return new Task(std::move(f), description, extraDescription); } -Task* createTask(uint32_t expiration, TaskFunc&& f) +Task* createTaskWithStats(uint32_t expiration, TaskFunc&& f, const std::string& description, const std::string& extraDescription) { - return new Task(expiration, std::move(f)); + return new Task(expiration, std::move(f), description, extraDescription); } void Dispatcher::threadMain() @@ -23,24 +23,41 @@ void Dispatcher::threadMain() std::vector tmpTaskList; // NOTE: second argument defer_lock is to prevent from immediate locking std::unique_lock taskLockUnique(taskLock, std::defer_lock); +#ifdef STATS_ENABLED + std::chrono::high_resolution_clock::time_point time_point; +#endif while (getState() != THREAD_STATE_TERMINATED) { // check if there are tasks waiting taskLockUnique.lock(); if (taskList.empty()) { //if the list is empty wait for signal +#ifdef STATS_ENABLED + time_point = std::chrono::high_resolution_clock::now(); taskSignal.wait(taskLockUnique); + g_stats.dispatcherWaitTime(dispatcherId) += std::chrono::duration_cast(std::chrono::high_resolution_clock::now() - time_point).count(); +#else + taskSignal.wait(taskLockUnique); +#endif } tmpTaskList.swap(taskList); taskLockUnique.unlock(); for (Task* task : tmpTaskList) { +#ifdef STATS_ENABLED + time_point = std::chrono::high_resolution_clock::now(); +#endif if (!task->hasExpired()) { ++dispatcherCycle; // execute it (*task)(); } +#ifdef STATS_ENABLED + task->executionTime = std::chrono::duration_cast(std::chrono::high_resolution_clock::now() - time_point).count(); + g_stats.addDispatcherTask(dispatcherId, task); +#else delete task; +#endif } tmpTaskList.clear(); } diff --git a/src/tasks.h b/src/tasks.h index bd7b91cf28..2eb831de97 100644 --- a/src/tasks.h +++ b/src/tasks.h @@ -7,6 +7,7 @@ #include #include "thread_holder_base.h" #include "enums.h" +#include "stats.h" using TaskFunc = std::function; const int DISPATCHER_TASK_EXPIRATION = 2000; @@ -16,9 +17,10 @@ class Task { public: // DO NOT allocate this class on the stack - explicit Task(TaskFunc&& f) : func(std::move(f)) {} - Task(uint32_t ms, TaskFunc&& f) : - expiration(std::chrono::system_clock::now() + std::chrono::milliseconds(ms)), func(std::move(f)) {} + explicit Task(TaskFunc&& f, const std::string& _description, const std::string& _extraDescription) : + func(std::move(f)), description(_description), extraDescription(_extraDescription) {} + Task(uint32_t ms, TaskFunc&& f, const std::string& _description, const std::string& _extraDescription) : + expiration(std::chrono::system_clock::now() + std::chrono::milliseconds(ms)), func(std::move(f)), description(_description), extraDescription(_extraDescription) {} virtual ~Task() = default; void operator()() { @@ -36,6 +38,10 @@ class Task return expiration < std::chrono::system_clock::now(); } + const std::string description; + const std::string extraDescription; + uint64_t executionTime = 0; + protected: std::chrono::system_clock::time_point expiration = SYSTEM_TIME_ZERO; @@ -46,11 +52,16 @@ class Task TaskFunc func; }; -Task* createTask(TaskFunc&& f); -Task* createTask(uint32_t expiration, TaskFunc&& f); +Task* createTaskWithStats(TaskFunc&& f, const std::string& description, const std::string& extraDescription); +Task* createTaskWithStats(uint32_t expiration, TaskFunc&& f, const std::string& description, const std::string& extraDescription); class Dispatcher : public ThreadHolder { public: + Dispatcher() : ThreadHolder() { + static int id = 0; + dispatcherId = id; + id += 1; + } void addTask(Task* task); void shutdown(); @@ -67,6 +78,7 @@ class Dispatcher : public ThreadHolder { std::vector taskList; uint64_t dispatcherCycle = 0; + int dispatcherId = 0; }; extern Dispatcher g_dispatcher; diff --git a/vc17/theforgottenserver.vcxproj b/vc17/theforgottenserver.vcxproj index bda892612c..d51ee5c700 100644 --- a/vc17/theforgottenserver.vcxproj +++ b/vc17/theforgottenserver.vcxproj @@ -228,6 +228,7 @@ + @@ -313,6 +314,7 @@ +