Core: improve logger performance

- Drop the need for the ImGui logger sink, we can just use the buffer we already rendered into for the terminal sink.
- Remove ANSI rows inserted by the logger before file logging using offsets and ranges to significantly improve the performance.
- For ANSI row constants, use std::string so appending can use the precomputed string length instead of running strlen() each time internally.

src/core/dllmain.cpp

@@ -59,7 +59,7 @@ void Show_Emblem()
     // Log the SDK's 'build_id' under the emblem.
     Msg(eDLL_T::SYSTEM_ERROR,
         "+------------------------------------------------[%s%010d%s]-+\n",
-        g_svYellowF, g_SDKDll.GetNTHeaders()->FileHeader.TimeDateStamp, g_svRedF);
+        g_svYellowF.c_str(), g_SDKDll.GetNTHeaders()->FileHeader.TimeDateStamp, g_svRedF.c_str());
     Msg(eDLL_T::SYSTEM_ERROR, "\n");
 }
 

src/core/logdef.cpp

@@ -2,13 +2,8 @@
 #include "core/logdef.h"
 
 std::shared_ptr<spdlog::logger> g_TermLogger;
-std::shared_ptr<spdlog::logger> g_ImGuiLogger;
-
 std::shared_ptr<spdlog::logger> g_SuppementalToolsLogger;
 
-std::ostringstream g_LogStream;
-std::shared_ptr<spdlog::sinks::ostream_sink_st> g_LogSink;
-
 #ifndef _TOOLS
 static void SpdLog_CreateRotatingLoggers()
 {
@@ -68,16 +63,6 @@ void SpdLog_Init(const bool bAnsiColor)
 	}
 
 	g_LogSessionDirectory = fmt::format("platform/logs/{:s}", g_LogSessionUUID);
-	/************************
-	 * IMGUI LOGGER SETUP   *
-	 ************************/
-	{
-		g_LogSink = std::make_shared<spdlog::sinks::ostream_sink_st>(g_LogStream);
-		g_ImGuiLogger = std::make_shared<spdlog::logger>("game_console", g_LogSink);
-		spdlog::register_logger(g_ImGuiLogger); // in-game console logger.
-		g_ImGuiLogger->set_pattern("%v");
-		g_ImGuiLogger->set_level(spdlog::level::trace);
-	}
 #endif // !_TOOLS
 	/************************
 	 * WINDOWS LOGGER SETUP *
@@ -99,7 +84,6 @@ void SpdLog_Init(const bool bAnsiColor)
 		{
 			g_TermLogger->set_pattern("%v");
 		}
-		//g_TermLogger->set_level(spdlog::level::trace);
 	}
 
 #ifndef _TOOLS

src/core/logdef.h

@@ -22,11 +22,6 @@ extern std::shared_ptr<spdlog::logger> g_ImGuiLogger;
 extern std::shared_ptr<spdlog::logger> g_SuppementalToolsLogger;
 #endif // _TOOLS
 
-//-------------------------------------------------------------------------
-// IMGUI CONSOLE SINK                                                     |
-extern std::ostringstream g_LogStream;
-extern std::shared_ptr<spdlog::sinks::ostream_sink_st> g_LogSink;
-
 void SpdLog_Init(const bool bAnsiColor);
 void SpdLog_Shutdown(void);
 

src/core/logger.cpp

@@ -72,21 +72,24 @@ ImVec4 GetColorForContext(LogType_t type, eDLL_T context)
 }
 #endif // !DEDICATED && !_TOOLS
 
-const char* GetContextNameByIndex(eDLL_T context, const bool ansiColor = false)
+static const char* GetContextNameByIndex(eDLL_T context, size_t& numTotalChars, size_t& numAnsiChars, const bool ansiColor)
 {
-	int index = static_cast<int>(context);
+	const int index = static_cast<int>(context);
-	const char* contextName = s_DefaultAnsiColor;
+	const char* contextName;
 
 	switch (context)
 	{
 	case eDLL_T::SCRIPT_SERVER:
 		contextName = s_ScriptAnsiColor[0];
+		numTotalChars = s_FullAnsiContextPrefixTextSize;
 		break;
 	case eDLL_T::SCRIPT_CLIENT:
 		contextName = s_ScriptAnsiColor[1];
+		numTotalChars = s_FullAnsiContextPrefixTextSize;
 		break;
 	case eDLL_T::SCRIPT_UI:
 		contextName = s_ScriptAnsiColor[2];
+		numTotalChars = s_FullAnsiContextPrefixTextSize;
 		break;
 	case eDLL_T::SERVER:
 	case eDLL_T::CLIENT:
@@ -102,17 +105,22 @@ const char* GetContextNameByIndex(eDLL_T context, const bool ansiColor = false)
 	case eDLL_T::SYSTEM_WARNING:
 	case eDLL_T::SYSTEM_ERROR:
 		contextName = s_DllAnsiColor[index];
+		numTotalChars = context >= eDLL_T::COMMON ? s_AnsiColorTextSize : s_FullAnsiContextPrefixTextSize;
 		break;
-	case eDLL_T::NONE:
 	default:
+		contextName = s_DefaultAnsiColor;
+		numTotalChars = s_AnsiColorTextSize;
 		break;
 	}
 
 	if (!ansiColor)
 	{
 		// Shift # chars to skip ANSI row.
-		contextName += sizeof(s_DefaultAnsiColor) - 1;
+		contextName += s_AnsiColorTextSize;
+		numTotalChars -= s_AnsiColorTextSize;
 	}
+	else
+		numAnsiChars = s_AnsiColorTextSize;
 
 	return contextName;
 }
@@ -147,11 +155,16 @@ void EngineLoggerSink(LogType_t logType, LogLevel_t logLevel, eDLL_T context,
 	const char* pszUpTime = pszUptimeOverride ? pszUptimeOverride : Plat_GetProcessUpTime();
 	string message(pszUpTime);
 
+	const size_t contextTextStartIndex = message.length();
+
 	const bool bToConsole = (logLevel >= LogLevel_t::LEVEL_CONSOLE);
 	const bool bUseColor = (bToConsole && g_bSpdLog_UseAnsiClr);
 
-	const char* pszContext = GetContextNameByIndex(context, bUseColor);
+	size_t numTotalContextTextChars = 0;
-	message.append(pszContext);
+	size_t numAnsiContextChars = 0;
+
+	const char* pszContext = GetContextNameByIndex(context, numTotalContextTextChars, numAnsiContextChars, bUseColor);
+	message.append(pszContext, numTotalContextTextChars);
 
 #if !defined (DEDICATED) && !defined (_TOOLS)
 	ImVec4 overlayColor = GetColorForContext(logType, context);
@@ -166,6 +179,9 @@ void EngineLoggerSink(LogType_t logType, LogLevel_t logLevel, eDLL_T context,
 	NOTE_UNUSED(pszLogger);
 #endif // !_TOOLS
 
+	const size_t messageTextStartIndex = message.length();
+	size_t numMessageAnsiChars = 0;
+
 	//-------------------------------------------------------------------------
 	// Setup logger and context
 	//-------------------------------------------------------------------------
@@ -178,6 +194,7 @@ void EngineLoggerSink(LogType_t logType, LogLevel_t logLevel, eDLL_T context,
 		if (bUseColor)
 		{
 			message.append(g_svYellowF);
+			numMessageAnsiChars = g_svYellowF.length();
 		}
 		break;
 	case LogType_t::LOG_ERROR:
@@ -187,6 +204,7 @@ void EngineLoggerSink(LogType_t logType, LogLevel_t logLevel, eDLL_T context,
 		if (bUseColor)
 		{
 			message.append(g_svRedF);
+			numMessageAnsiChars = g_svRedF.length();
 		}
 		break;
 #ifndef _TOOLS
@@ -248,12 +266,28 @@ void EngineLoggerSink(LogType_t logType, LogLevel_t logLevel, eDLL_T context,
 
 			if (bUseColor)
 			{
-				message.append(g_svRedF);
+				if (logType != LogType_t::LOG_ERROR)
+				{
+					if (numMessageAnsiChars > 0)
+						message.replace(messageTextStartIndex, numMessageAnsiChars, g_svRedF);
+					else
+						message.append(g_svRedF);
+
+					numMessageAnsiChars = g_svRedF.length();
+				}
 			}
 		}
 		else if (bUseColor && bWarning)
 		{
-			message.append(g_svYellowF);
+			if (logType != LogType_t::LOG_ERROR)
+			{
+				if (numMessageAnsiChars > 0)
+					message.replace(messageTextStartIndex, numMessageAnsiChars, g_svYellowF);
+				else
+					message.append(g_svYellowF);
+
+				numMessageAnsiChars = g_svYellowF.length();
+			}
 		}
 	}
 #endif // !_TOOLS
@@ -267,9 +301,24 @@ void EngineLoggerSink(LogType_t logType, LogLevel_t logLevel, eDLL_T context,
 	{
 		g_TermLogger->debug(message);
 
+		// Remove ANSI rows if we have them, before emitting to file or over wire.
 		if (bUseColor)
 		{
-			// Remove ANSI rows before emitting to file or over wire.
+			// Start with the message first because else the indices will shift.
+			// The message colors comes after the context colors.
+			if (numMessageAnsiChars > 0)
+			{
+				message.erase(messageTextStartIndex, numMessageAnsiChars);
+				numMessageAnsiChars = 0;
+			}
+
+			if (numAnsiContextChars > 0)
+			{
+				message.erase(contextTextStartIndex, numAnsiContextChars);
+				numAnsiContextChars = 0;
+			}
+
+			// Remove anything else that was passed in as a format argument.
 			message = std::regex_replace(message, s_AnsiRowRegex, "");
 		}
 	}
@@ -282,7 +331,9 @@ void EngineLoggerSink(LogType_t logType, LogLevel_t logLevel, eDLL_T context,
 	// Output is always logged to the file.
 	std::shared_ptr<spdlog::logger> ntlogger = spdlog::get(pszLogger); // <-- Obtain by 'pszLogger'.
 	assert(ntlogger.get() != nullptr);
-	ntlogger->debug(message);
+
+	if (ntlogger)
+		ntlogger->debug(message);
 
 	if (bToConsole)
 	{
@@ -294,26 +345,18 @@ void EngineLoggerSink(LogType_t logType, LogLevel_t logLevel, eDLL_T context,
 		}
 #endif // !CLIENT_DLL
 #ifndef DEDICATED
-		g_ImGuiLogger->debug(message);
+		g_Console.AddLog(message.c_str(), ImGui::ColorConvertFloat4ToU32(overlayColor));
-
-		const string logStreamBuf = g_LogStream.str();
-		g_Console.AddLog(logStreamBuf.c_str(), ImGui::ColorConvertFloat4ToU32(overlayColor));
 
 		// We can only log to the in-game overlay console when the SDK has
 		// been fully initialized, due to the use of ConVar's.
 		if (g_bSdkInitialized && logLevel >= LogLevel_t::LEVEL_NOTIFY)
 		{
 			// Draw to mini console.
-			g_TextOverlay.AddLog(overlayContext, logStreamBuf.c_str());
+			g_TextOverlay.AddLog(overlayContext, message.c_str());
 		}
 #endif // !DEDICATED
 	}
 
-#ifndef DEDICATED
-	g_LogStream.str(string());
-	g_LogStream.clear();
-#endif // !DEDICATED
-
 #else
 	if (g_SuppementalToolsLogger)
 	{

src/core/termutil.cpp

@@ -1,19 +1,19 @@
 #include "core/stdafx.h"
 #include "core/termutil.h"
 
-const char* g_svGreyF   = "";
+std::string g_svGreyF;
-const char* g_svRedF    = "";
+std::string g_svRedF;
-const char* g_svGreenF  = "";
+std::string g_svGreenF;
-const char* g_svBlueF   = "";
+std::string g_svBlueF;
-const char* g_svYellowF = "";
+std::string g_svYellowF;
 
-const char* g_svGreyB   = "";
+std::string g_svGreyB;
-const char* g_svRedB    = "";
+std::string g_svRedB;
-const char* g_svGreenB  = "";
+std::string g_svGreenB;
-const char* g_svBlueB   = "";
+std::string g_svBlueB;
-const char* g_svYellowB = "";
+std::string g_svYellowB;
 
-const char* g_svReset   = "";
+std::string g_svReset;
 
 //-----------------------------------------------------------------------------
 // Purpose: sets the global ansi escape sequences.

src/core/termutil.h

@@ -1,16 +1,16 @@
 #pragma once
-extern const char* g_svGreyF;
+extern std::string g_svGreyF;
-extern const char* g_svRedF;
+extern std::string g_svRedF;
-extern const char* g_svGreenF;
+extern std::string g_svGreenF;
-extern const char* g_svBlueF;
+extern std::string g_svBlueF;
-extern const char* g_svYellowF;
+extern std::string g_svYellowF;
 
-extern const char* g_svGreyB;
+extern std::string g_svGreyB;
-extern const char* g_svRedB;
+extern std::string g_svRedB;
-extern const char* g_svGreenB;
+extern std::string g_svGreenB;
-extern const char* g_svBlueB;
+extern std::string g_svBlueB;
-extern const char* g_svYellowB;
+extern std::string g_svYellowB;
 
-extern const char* g_svReset;
+extern std::string g_svReset;
 
 void AnsiColors_Init();

src/engine/host_state.cpp

@@ -121,8 +121,8 @@ static void HostState_KeepAlive()
 						{
 							g_ServerHostManager.SetCurrentToken(hostToken);
 							Msg(eDLL_T::SERVER, "Published server with token: %s'%s%s%s'\n",
-								g_svReset, g_svGreyB,
+								g_svReset.c_str(), g_svGreyB.c_str(),
-								hostToken.c_str(), g_svReset);
+								hostToken.c_str(), g_svReset.c_str());
 						}
 					}
 

src/engine/net.cpp

@@ -181,7 +181,7 @@ void NET_Config()
 void NET_PrintKey()
 {
 	Msg(eDLL_T::ENGINE, "Installed NetKey: %s'%s%s%s'\n",
-		g_svReset, g_svGreyB, g_pNetKey->GetBase64NetKey(), g_svReset);
+		g_svReset.c_str(), g_svGreyB.c_str(), g_pNetKey->GetBase64NetKey(), g_svReset.c_str());
 }
 
 //-----------------------------------------------------------------------------

src/engine/server/sv_rcon.cpp

@@ -95,7 +95,7 @@ void CRConServer::Init(const char* pPassword, const char* pNetKey)
 	m_Socket.CreateListenSocket(m_Address);
 
 	Msg(eDLL_T::SERVER, "Remote server access initialized ('%s') with key %s'%s%s%s'\n",
-		m_Address.ToString(), g_svReset, g_svGreyB, GetKey(), g_svReset);
+		m_Address.ToString(), g_svReset.c_str(), g_svGreyB.c_str(), GetKey(), g_svReset.c_str());
 
 	m_bInitialized = true;
 }

src/engine/shared/shared_rcon.cpp

@@ -344,19 +344,19 @@ void RCON_KeyChanged_f(IConVar* pConVar, const char* pOldString, float flOldValu
 		RCONClient()->SetKey(RCONServer()->GetKey()); // Sync server & client keys
 
 		Msg(eDLL_T::ENGINE, "Installed RCON Key: %s'%s%s%s'\n",
-			g_svReset, g_svGreyB, RCONClient()->GetKey(), g_svReset);
+			g_svReset.c_str(), g_svGreyB.c_str(), RCONClient()->GetKey(), g_svReset.c_str());
 #else
 #ifdef DEDICATED
 		RCONServer()->SetKey(pNewString);
 
 		Msg(eDLL_T::SERVER, "Installed RCON Key: %s'%s%s%s'\n",
-			g_svReset, g_svGreyB, RCONServer()->GetKey(), g_svReset);
+			g_svReset.c_str(), g_svGreyB.c_str(), RCONServer()->GetKey(), g_svReset.c_str());
 #endif // DEDICATED
 #ifdef CLIENT_DLL
 		RCONClient()->SetKey(pNewString);
 
 		Msg(eDLL_T::CLIENT, "Installed RCON Key: %s'%s%s%s'\n",
-			g_svReset, g_svGreyB, RCONClient()->GetKey(), g_svReset);
+			g_svReset.c_str(), g_svGreyB.c_str(), RCONClient()->GetKey(), g_svReset.c_str());
 #endif // CLIENT_DLL
 
 #endif // !DEDICATED && !CLIENT_DLL

src/netconsole/netconsole.cpp

@@ -193,7 +193,7 @@ void CNetCon::TrySetKey(const char* const pKey)
 	if (!*pKey)
 	{
 		Warning(eDLL_T::CLIENT, "No key provided; using default %s'%s%s%s'\n",
-			g_svReset, g_svGreyB, DEFAULT_NET_ENCRYPTION_KEY, g_svReset);
+			g_svReset.c_str(), g_svGreyB.c_str(), DEFAULT_NET_ENCRYPTION_KEY, g_svReset.c_str());
 
 		SetKey(DEFAULT_NET_ENCRYPTION_KEY, true);
 	}
@@ -377,7 +377,7 @@ bool CNetCon::Connect(const char* pHostName, const int nPort)
 	if (m_bEncryptFrames)
 	{
 		Msg(eDLL_T::CLIENT, "Attempting connection to '%s' with key %s'%s%s%s'\n",
-			pHostName, g_svReset, g_svGreyB, GetKey(), g_svReset);
+			pHostName, g_svReset.c_str(), g_svGreyB.c_str(), GetKey(), g_svReset.c_str());
 	}
 	else
 	{

src/public/tier0/dbg.h

@@ -95,6 +95,11 @@ constexpr const char* s_ScriptAnsiColor[4] =
 	"\033[38;2;151;149;163mScript(X):"
 };
 
+// "Native", "Script" and "Netcon" have the same length, so we can cheat here.
+constexpr size_t s_ContextPrefixTextSize = sizeof("Native(X):") - 1;
+constexpr size_t s_AnsiColorTextSize = sizeof(s_CommonAnsiColor) - 1;
+constexpr size_t s_FullAnsiContextPrefixTextSize = s_AnsiColorTextSize + s_ContextPrefixTextSize;
+
 //////////////////////////////////////////////////////////////////////////
 // Legacy Logging System
 //////////////////////////////////////////////////////////////////////////