diff --git a/CMakeLists.txt b/CMakeLists.txt index 84bd72efc..60d650083 100644 --- a/CMakeLists.txt +++ b/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 diff --git a/config.lua.dist b/config.lua.dist index d1e47a552..45c484344 100644 --- a/config.lua.dist +++ b/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 diff --git a/data/logs/.gitignore b/data/logs/.gitignore deleted file mode 100644 index 5e7d2734c..000000000 --- a/data/logs/.gitignore +++ /dev/null @@ -1,4 +0,0 @@ -# Ignore everything in this directory -* -# Except this file -!.gitignore diff --git a/data/logs/stats/.gitignore b/data/logs/stats/.gitignore new file mode 100644 index 000000000..bf0824e59 --- /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 51701568a..2d9b28f7b 100644 --- a/src/CMakeLists.txt +++ b/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 diff --git a/src/configmanager.cpp b/src/configmanager.cpp index 7483c5496..bb7a6059d 100644 --- a/src/configmanager.cpp +++ b/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()) { diff --git a/src/configmanager.h b/src/configmanager.h index 408a8b4c2..11e5d07e3 100644 --- a/src/configmanager.h +++ b/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 */ }; diff --git a/src/database.cpp b/src/database.cpp index 8e74801e7..7ad04664b 100644 --- a/src/database.cpp +++ b/src/database.cpp @@ -21,6 +21,7 @@ #include "configmanager.h" #include "database.h" +#include "stats.h" #include @@ -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::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::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 039e32512..1e59a4c86 100644 --- a/src/game.cpp +++ b/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(); diff --git a/src/luascript.cpp b/src/luascript.cpp index 55a2715fb..be98b55b7 100644 --- a/src/luascript.cpp +++ b/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::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 ce5f1bd54..a17594a64 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/otpch.h b/src/otpch.h index dce4b3544..2fcedfcd1 100644 --- a/src/otpch.h +++ b/src/otpch.h @@ -39,6 +39,7 @@ #include #include #include +#include #include diff --git a/src/otserv.cpp b/src/otserv.cpp index 9469db323..a6cb7f529 100644 --- a/src/otserv.cpp +++ b/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; } diff --git a/src/protocolgame.h b/src/protocolgame.h index dba2874fe..b12c4fd73 100644 --- a/src/protocolgame.h +++ b/src/protocolgame.h @@ -271,13 +271,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 37cbf3c4b..ef9ba8020 100644 --- a/src/scheduler.cpp +++ b/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); } diff --git a/src/scheduler.h b/src/scheduler.h index f0526b569..0519e8f99 100644 --- a/src/scheduler.h +++ b/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 { diff --git a/src/signals.cpp b/src/signals.cpp index 8319e0590..b8c4447d8 100644 --- a/src/signals.cpp +++ b/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: diff --git a/src/stats.cpp b/src/stats.cpp new file mode 100644 index 000000000..3baa7e53c --- /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(); +} \ No newline at end of file diff --git a/src/stats.h b/src/stats.h new file mode 100644 index 000000000..8da745233 --- /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 \ No newline at end of file diff --git a/src/tasks.cpp b/src/tasks.cpp index b792aeb81..136315804 100644 --- a/src/tasks.cpp +++ b/src/tasks.cpp @@ -24,14 +24,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() @@ -40,23 +40,41 @@ void Dispatcher::threadMain() // 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 - taskSignal.wait(taskLockUnique); + #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)(); } - delete 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 627008f11..32aca2b9e 100644 --- a/src/tasks.h +++ b/src/tasks.h @@ -23,6 +23,7 @@ #include #include "thread_holder_base.h" #include "enums.h" +#include "stats.h" using TaskFunc = std::function; const int DISPATCHER_TASK_EXPIRATION = 2000; @@ -32,9 +33,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()() { @@ -52,6 +54,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; @@ -62,11 +68,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(); @@ -83,6 +94,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 5b76e9239..00c56980c 100644 --- a/vc17/theforgottenserver.vcxproj +++ b/vc17/theforgottenserver.vcxproj @@ -225,6 +225,7 @@ + @@ -306,6 +307,7 @@ +