diff --git a/CMakeLists.txt b/CMakeLists.txt index b9c47d4a18..4663208452 100644 --- a/CMakeLists.txt +++ b/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) diff --git a/config.lua.dist b/config.lua.dist index 8c0498d196..49ed950e58 100644 --- a/config.lua.dist +++ b/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 diff --git a/data/cpplinter.lua b/data/cpplinter.lua index 233e9c482a..cb7c6ecb0c 100644 --- a/data/cpplinter.lua +++ b/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 diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index 3c09a5a534..f975e0831d 100644 --- a/src/CMakeLists.txt +++ b/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 diff --git a/src/configmanager.cpp b/src/configmanager.cpp index f3ec1170f0..8920038bcb 100644 --- a/src/configmanager.cpp +++ b/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()) { diff --git a/src/configmanager.h b/src/configmanager.h index 8268afc107..adac6ba916 100644 --- a/src/configmanager.h +++ b/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 */ }; diff --git a/src/database.cpp b/src/database.cpp index 91f644ce8e..229f87563b 100644 --- a/src/database.cpp +++ b/src/database.cpp @@ -6,6 +6,7 @@ #include "database.h" #include "configmanager.h" +#include "stats.h" #include @@ -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,13 @@ 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::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; } diff --git a/src/game.cpp b/src/game.cpp index e1f143310b..069cb8566f 100644 --- a/src/game.cpp +++ b/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(); diff --git a/src/luascript.cpp b/src/luascript.cpp index e50774e163..f390ce6144 100644 --- a/src/luascript.cpp +++ b/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::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(addEventStackBacktrace.c_str()), + addEventStackBacktrace.length()))); + uint64_t ns = + std::chrono::duration_cast(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::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"; } diff --git a/src/luascript.h b/src/luascript.h index 9bafa7bc68..0f4941b87b 100644 --- a/src/luascript.h +++ b/src/luascript.h @@ -42,6 +42,9 @@ struct LuaTimerEventDesc int32_t function = -1; std::vector 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 cacheFiles; +#ifdef STATS_ENABLED + std::map addEventStackTracebackHashCache; +#endif private: // lua functions diff --git a/src/otserv.cpp b/src/otserv.cpp index c497f09ee1..15589e5c0a 100644 --- a/src/otserv.cpp +++ b/src/otserv.cpp @@ -21,6 +21,7 @@ #include "script.h" #include "scriptmanager.h" #include "server.h" +#include "stats.h" #include @@ -31,6 +32,7 @@ DatabaseTasks g_databaseTasks; Dispatcher g_dispatcher; Scheduler g_scheduler; +Stats g_stats; Game g_game; Monsters g_monsters; @@ -281,6 +283,9 @@ void startServer() g_dispatcher.start(); g_scheduler.start(); +#ifdef STATS_ENABLED + g_stats.start(); +#endif g_dispatcher.addTask([services = &serviceManager]() { mainLoader(services); }); @@ -294,11 +299,17 @@ void startServer() 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 } void printServerVersion() diff --git a/src/signals.cpp b/src/signals.cpp index c8ef9cb5ac..6ae2109e48 100644 --- a/src/signals.cpp +++ b/src/signals.cpp @@ -17,6 +17,7 @@ #include "npc.h" #include "scheduler.h" #include "spells.h" +#include "stats.h" #include "talkaction.h" #include "tasks.h" #include "weapons.h" @@ -152,6 +153,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..12b7796df1 --- /dev/null +++ b/src/stats.cpp @@ -0,0 +1,189 @@ +#include "otpch.h" + +#include "stats.h" + +#include "configmanager.h" +#include "tasks.h" +#include "tools.h" + +#include + +int64_t Stats::DUMP_INTERVAL = 30000; +uint32_t Stats::SLOW_EXECUTION_TIME = 10000000; +uint32_t Stats::VERY_SLOW_EXECUTION_TIME = 50000000; + +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; + + while (true) { + taskLockUnique.lock(); + + DUMP_INTERVAL = getNumber(ConfigManager::STATS_DUMP_INTERVAL) * 1000; + SLOW_EXECUTION_TIME = getNumber(ConfigManager::STATS_SLOW_LOG_TIME) * 1000000; + VERY_SLOW_EXECUTION_TIME = getNumber(ConfigManager::STATS_VERY_SLOW_LOG_TIME) * 1000000; + + std::forward_list lua_stats(std::move(lua.queue)); + lua.queue.clear(); + std::forward_list sql_stats(std::move(sql.queue)); + sql.queue.clear(); + std::forward_list special_stats(std::move(special.queue)); + special.queue.clear(); + taskLockUnique.unlock(); + + parseLuaQueue(lua_stats); + parseSqlQueue(sql_stats); + parseSpecialQueue(special_stats); + + 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::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::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("stats/") + file, std::ofstream::out | std::ofstream::app); + if (!out.is_open()) { + std::clog << "Can't open " << std::string("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) const +{ + if (DUMP_INTERVAL == 0) { + return; + } + + std::ofstream out(std::string("stats/") + file, std::ofstream::out | std::ofstream::app); + if (!out.is_open()) { + std::clog << "Can't open " << std::string("stats/") + file << " (check if directory exists)" << std::endl; + return; + } + if (stats.empty()) { + out.close(); + return; + } + out << "[" << formatDate(time(nullptr)) << "] Players online: " << playersOnline << "\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 * static_cast(it.second.executionTime) / total_time; + float realPercent = static_cast(it.second.executionTime) / (static_cast(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..310b6d2807 --- /dev/null +++ b/src/stats.h @@ -0,0 +1,110 @@ +#ifndef TFS_STATS_H +#define TFS_STATS_H + +#include "thread_holder_base.h" + +class Task; + +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 addLuaStats(Stat* stats); + void addSqlStats(Stat* stats); + void addSpecialStats(Stat* stats); + + static uint32_t SLOW_EXECUTION_TIME; + static uint32_t VERY_SLOW_EXECUTION_TIME; + static int64_t DUMP_INTERVAL; + + std::atomic playersOnline; + +private: + 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); + void writeStats(const std::string& file, const statsMap& stats, const std::string& extraInfo = "") const; + + std::mutex statsLock; + struct + { + std::forward_list queue; + statsMap stats; + int64_t lastDump; + } lua, sql, special; +}; + +extern Stats g_stats; + +class AutoStat +{ +public: + explicit 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: + explicit 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/tools.cpp b/src/tools.cpp index d950718c4f..5226f439bf 100644 --- a/src/tools.cpp +++ b/src/tools.cpp @@ -134,6 +134,19 @@ std::string generateToken(std::string_view key, uint64_t counter, size_t length return token.substr(token.size() - length); } +void replaceString(std::string& str, const std::string& sought, const std::string& replacement) +{ + size_t pos = 0; + size_t start = 0; + size_t soughtLen = sought.length(); + size_t replaceLen = replacement.length(); + + while ((pos = str.find(sought, start)) != std::string::npos) { + str = str.substr(0, pos) + replacement + str.substr(pos + soughtLen); + start = pos + replaceLen; + } +} + bool caseInsensitiveEqual(std::string_view str1, std::string_view str2) { return str1.size() == str2.size() && diff --git a/src/tools.h b/src/tools.h index 97b2381718..1e63823e1d 100644 --- a/src/tools.h +++ b/src/tools.h @@ -14,6 +14,7 @@ std::string transformToSHA1(std::string_view input); std::string hmac(std::string_view algorithm, std::string_view key, std::string_view message); std::string generateToken(std::string_view key, uint64_t counter, size_t length = AUTHENTICATOR_DIGITS); +void replaceString(std::string& str, const std::string& sought, const std::string& replacement); // checks that str1 is equivalent to str2 ignoring letter case bool caseInsensitiveEqual(std::string_view str1, std::string_view str2); diff --git a/stats/.gitignore b/stats/.gitignore new file mode 100644 index 0000000000..397b4a7624 --- /dev/null +++ b/stats/.gitignore @@ -0,0 +1 @@ +*.log diff --git a/vc17/theforgottenserver.vcxproj b/vc17/theforgottenserver.vcxproj index 09c24293be..04fe28c5ee 100644 --- a/vc17/theforgottenserver.vcxproj +++ b/vc17/theforgottenserver.vcxproj @@ -95,7 +95,7 @@ - _CONSOLE;$(PREPROCESSOR_DEFS);%(PreprocessorDefinitions) + _CONSOLE;STATS_ENABLED;$(PREPROCESSOR_DEFS);%(PreprocessorDefinitions) ProgramDatabase Disabled true @@ -111,7 +111,7 @@ - _CONSOLE;$(PREPROCESSOR_DEFS);%(PreprocessorDefinitions) + _CONSOLE;STATS_ENABLED;$(PREPROCESSOR_DEFS);%(PreprocessorDefinitions) ProgramDatabase true AdvancedVectorExtensions @@ -125,7 +125,7 @@ - NDEBUG;_CONSOLE;$(PREPROCESSOR_DEFS);%(PreprocessorDefinitions) + NDEBUG;_CONSOLE;STATS_ENABLED;$(PREPROCESSOR_DEFS);%(PreprocessorDefinitions) MultiThreadedDLL ProgramDatabase MaxSpeed @@ -146,7 +146,7 @@ - NDEBUG;_CONSOLE;$(PREPROCESSOR_DEFS);%(PreprocessorDefinitions) + NDEBUG;_CONSOLE;STATS_ENABLED;$(PREPROCESSOR_DEFS);%(PreprocessorDefinitions) MultiThreadedDLL ProgramDatabase Level4 @@ -245,6 +245,7 @@ + @@ -337,6 +338,7 @@ +