perf: optimized logging with profiling and efficient file management …

…(#7777) (opentibiabr#2832)

This improves the performance of the logging system and adds
profiling functionality with automatic log generation. Additionally,
optimizations have been performed to ensure that logs are written
efficiently to text files.

---------
Co-authored-by: Eduardo Dantas <eduardo.dantas@hotmail.com.br>

cmake/modules/BaseConfig.cmake

@@ -87,6 +87,7 @@ endif()
 # cmake -DDEBUG_LOG=ON ..
 if(DEBUG_LOG)
     add_definitions(-DDEBUG_LOG=ON)
+    add_definitions(-DSPDLOG_ACTIVE_LEVEL=SPDLOG_LEVEL_TRACE)
     log_option_enabled("DEBUG LOG")
 else()
     log_option_disabled("DEBUG LOG")

config.lua.dist

@@ -9,7 +9,8 @@ coreDirectory = "data"
 
 -- Set log level
 -- It can be trace, debug, info, warning, error, critical, off (default: info).
--- NOTE: Will only display logs with level higher or equal the one set.
+-- NOTE: It will only be valid after the server starts up and only display logs with level higher or equal the one set.
+-- NOTE: Debug and trace logs are only available if compiled in debug mode.
 logLevel = "info"
 
 --- Toggles the server's maintenance mode.
@@ -52,7 +53,7 @@ cleanProtectionZones = false
 -- Connection Config
 -- NOTE: allowOldProtocol can allow login on 10x protocol. (11.00)
 -- NOTE: maxPlayers set to 0 means no limit
--- NOTE: MaxPacketsPerSeconds if you change you will be subject to bugs by WPE, keep the default value of 25, 
+-- NOTE: MaxPacketsPerSeconds if you change you will be subject to bugs by WPE, keep the default value of 25,
 -- It's recommended to use a range like min 50 in this function, otherwise you will be disconnected after equipping two-handed distance weapons.
 ip = "127.0.0.1"
 allowOldProtocol = false

src/account/account.cpp

@@ -14,7 +14,6 @@
 #include "utils/definitions.hpp"
 #include "security/argon.hpp"
 #include "utils/tools.hpp"
-#include "lib/logging/log_with_spd_log.hpp"
 
 #include "enums/account_type.hpp"
 #include "enums/account_coins.hpp"

src/account/account_repository_db.cpp

@@ -10,7 +10,6 @@
 #include "account/account_repository_db.hpp"
 
 #include "database/database.hpp"
-#include "lib/logging/logger.hpp"
 #include "utils/definitions.hpp"
 #include "utils/tools.hpp"
 #include "enums/account_type.hpp"

src/canary_server.cpp

@@ -97,7 +97,6 @@ int CanaryServer::run() {
 #endif
 
 				g_game().start(&serviceManager);
-				g_game().setGameState(GAME_STATE_NORMAL);
 				if (g_configManager().getBoolean(TOGGLE_MAINTAIN_MODE)) {
 					g_game().setGameState(GAME_STATE_CLOSED);
 					g_logger().warn("Initialized in maintain mode!");
@@ -133,6 +132,7 @@ int CanaryServer::run() {
 	}
 
 	logger.info("{} {}", g_configManager().getString(SERVER_NAME), "server online!");
+	g_logger().setLevel(g_configManager().getString(LOGLEVEL));
 
 	serviceManager.run();
 
@@ -203,7 +203,7 @@ void CanaryServer::logInfos() {
 	logger.info("{} - Version {}", ProtocolStatus::SERVER_NAME, SERVER_RELEASE_VERSION);
 #endif
 
-	logger.debug("Compiled with {}, on {} {}, for platform {}\n", getCompiler(), __DATE__, __TIME__, getPlatform());
+	logger.debug("Compiled with {}, on {} {}, for platform {}", getCompiler(), __DATE__, __TIME__, getPlatform());
 
 #if defined(LUAJIT_VERSION)
 	logger.debug("Linked with {} for Lua support", LUAJIT_VERSION);

src/config/configmanager.cpp

@@ -35,10 +35,6 @@ bool ConfigManager::load() {
 		return false;
 	}
 
-#ifndef DEBUG_LOG
-	g_logger().setLevel(loadStringConfig(L, LOGLEVEL, "logLevel", "info"));
-#endif
-
 	// Parse config
 	// Info that must be loaded one time (unless we reset the modules involved)
 	if (!loaded) {
@@ -363,6 +359,7 @@ bool ConfigManager::load() {
 	loadStringConfig(L, TIBIADROME_CONCOCTION_TICK_TYPE, "tibiadromeConcoctionTickType", "online");
 	loadStringConfig(L, URL, "url", "");
 	loadStringConfig(L, WORLD_TYPE, "worldType", "pvp");
+	loadStringConfig(L, LOGLEVEL, "logLevel", "info");
 
 	loaded = true;
 	lua_close(L);

src/database/database.hpp

@@ -10,7 +10,6 @@
 #pragma once
 
 #include "declarations.hpp"
-#include "lib/logging/log_with_spd_log.hpp"
 
 #ifndef USE_PRECOMPILED_HEADERS
 	#include <mysql/mysql.h>

src/game/scheduling/task.cpp

@@ -9,7 +9,6 @@
 
 #include "task.hpp"
 
-#include "lib/logging/log_with_spd_log.hpp"
 #include "lib/metrics/metrics.hpp"
 
 std::atomic_uint_fast64_t Task::LAST_EVENT_ID = 0;

src/kv/kv.hpp

@@ -20,7 +20,6 @@
 	#include <list>
 #endif
 
-#include "lib/logging/logger.hpp"
 #include "kv/value_wrapper.hpp"
 
 class KV : public std::enable_shared_from_this<KV> {

src/kv/kv_sql.cpp

@@ -10,7 +10,6 @@
 #include "kv/kv_sql.hpp"
 
 #include "database/database.hpp"
-#include "lib/logging/logger.hpp"
 #include "kv/value_wrapper_proto.hpp"
 #include "utils/tools.hpp"
 

src/lib/CMakeLists.txt

@@ -1,5 +1,6 @@
 target_sources(${PROJECT_NAME}_lib PRIVATE
     di/soft_singleton.cpp
+    logging/logger.cpp
     logging/log_with_spd_log.cpp
     thread/thread_pool.cpp
 )

src/lib/di/soft_singleton.hpp

@@ -9,7 +9,6 @@
 #pragma once
 
 #include <iostream>
-#include "lib/logging/log_with_spd_log.hpp"
 
 class SoftSingleton {
 public:

src/lib/logging/log_with_spd_log.cpp

@@ -6,8 +6,8 @@
  * Contributors: https://github.com/opentibiabr/canary/graphs/contributors
  * Website: https://docs.opentibiabr.com/
  */
-#include <spdlog/spdlog.h>
 
+#include <spdlog/spdlog.h>
 #include "lib/di/container.hpp"
 
 LogWithSpdLog::LogWithSpdLog() {
@@ -23,17 +23,39 @@ Logger &LogWithSpdLog::getInstance() {
 	return inject<Logger>();
 }
 
-void LogWithSpdLog::setLevel(const std::string &name) {
+void LogWithSpdLog::setLevel(const std::string &name) const {
 	debug("Setting log level to: {}.", name);
-	auto level = spdlog::level::from_str(name);
+	const auto level = spdlog::level::from_str(name);
 	spdlog::set_level(level);
 }
 
 std::string LogWithSpdLog::getLevel() const {
-	auto level = spdlog::level::to_string_view(spdlog::get_level());
+	const auto level = spdlog::level::to_string_view(spdlog::get_level());
 	return std::string { level.begin(), level.end() };
 }
 
-void LogWithSpdLog::log(const std::string &lvl, const fmt::basic_string_view<char> msg) const {
-	spdlog::log(spdlog::level::from_str(lvl), msg);
+void LogWithSpdLog::info(const std::string &msg) const {
+	SPDLOG_INFO(msg);
+}
+
+void LogWithSpdLog::warn(const std::string &msg) const {
+	SPDLOG_WARN(msg);
 }
+
+void LogWithSpdLog::error(const std::string &msg) const {
+	SPDLOG_ERROR(msg);
+}
+
+void LogWithSpdLog::critical(const std::string &msg) const {
+	SPDLOG_CRITICAL(msg);
+}
+
+#if defined(DEBUG_LOG)
+void LogWithSpdLog::debug(const std::string &msg) const {
+	SPDLOG_DEBUG(msg);
+}
+
+void LogWithSpdLog::trace(const std::string &msg) const {
+	SPDLOG_TRACE(msg);
+}
+#endif

src/lib/logging/log_with_spd_log.hpp

@@ -17,10 +17,37 @@ class LogWithSpdLog final : public Logger {
 
 	static Logger &getInstance();
 
-	void setLevel(const std::string &name) override;
+	void setLevel(const std::string &name) const override;
 	std::string getLevel() const override;
 
-	void log(const std::string &lvl, fmt::basic_string_view<char> msg) const override;
+	void info(const std::string &msg) const override;
+	void warn(const std::string &msg) const override;
+	void error(const std::string &msg) const override;
+	void critical(const std::string &msg) const override;
+
+#if defined(DEBUG_LOG)
+	void debug(const std::string &msg) const override;
+	void trace(const std::string &msg) const override;
+
+	template <typename... Args>
+	void debug(const fmt::format_string<Args...> &fmt, Args &&... args) const {
+		debug(fmt::format(fmt, std::forward<Args>(args)...));
+	}
+
+	template <typename... Args>
+	void trace(const fmt::format_string<Args...> &fmt, Args &&... args) const {
+		trace(fmt::format(fmt, std::forward<Args>(args)...));
+	}
+#else
+	void debug(const std::string &) const override { }
+	void trace(const std::string &) const override { }
+
+	template <typename... Args>
+	void debug(const fmt::format_string<Args...> &, Args &&...) const { }
+
+	template <typename... Args>
+	void trace(const fmt::format_string<Args...> &, Args &&...) const { }
+#endif
 };
 
 constexpr auto g_logger = LogWithSpdLog::getInstance;

src/lib/logging/logger.cpp

@@ -0,0 +1,74 @@
+/**
+ * Canary - A free and open-source MMORPG server emulator
+ * Copyright (©) 2019-2024 OpenTibiaBR <opentibiabr@outlook.com>
+ * Repository: https://github.com/opentibiabr/canary
+ * License: https://github.com/opentibiabr/canary/blob/main/LICENSE
+ * Contributors: https://github.com/opentibiabr/canary/graphs/contributors
+ * Website: https://docs.opentibiabr.com/
+ */
+
+#include <spdlog/spdlog.h>
+#include <spdlog/sinks/basic_file_sink.h>
+#include <spdlog/sinks/stdout_color_sinks.h>
+#include "lib/di/container.hpp"
+
+void Logger::setLevel(const std::string &name) const {
+	debug("Setting log level to: {}.", name);
+	const auto level = spdlog::level::from_str(name);
+	spdlog::set_level(level);
+}
+
+std::string Logger::getLevel() const {
+	const auto level = spdlog::level::to_string_view(spdlog::get_level());
+	return std::string { level.begin(), level.end() };
+}
+
+void Logger::logProfile(const std::string &name, double duration_ms) const {
+	std::string mutable_name = name;
+
+	std::ranges::replace(mutable_name, ':', '_');
+	std::ranges::replace(mutable_name, '\\', '_');
+	std::ranges::replace(mutable_name, '/', '_');
+
+	std::string filename = "log/profile_log-" + mutable_name + ".txt";
+
+	const auto it = profile_loggers_.find(filename);
+	if (it == profile_loggers_.end()) {
+		try {
+			auto file_sink = std::make_shared<spdlog::sinks::basic_file_sink_mt>(filename, true);
+			const auto profile_logger = std::make_shared<spdlog::logger>(mutable_name, file_sink);
+			profile_loggers_[filename] = profile_logger;
+			profile_logger->info("Function {} executed in {} ms", name, duration_ms);
+		} catch (const spdlog::spdlog_ex &ex) {
+			error("Profile log initialization failed: {}", ex.what());
+		}
+	} else {
+		it->second->info("Function {} executed in {} ms", mutable_name, duration_ms);
+	}
+}
+
+void Logger::info(const std::string &msg) const {
+	SPDLOG_INFO(msg);
+}
+
+void Logger::warn(const std::string &msg) const {
+	SPDLOG_WARN(msg);
+}
+
+void Logger::error(const std::string &msg) const {
+	SPDLOG_ERROR(msg);
+}
+
+void Logger::critical(const std::string &msg) const {
+	SPDLOG_CRITICAL(msg);
+}
+
+#if defined(DEBUG_LOG)
+void Logger::debug(const std::string &msg) const {
+	SPDLOG_DEBUG(msg);
+}
+
+void Logger::trace(const std::string &msg) const {
+	SPDLOG_TRACE(msg);
+}
+#endif