Make logging cost free when there is no output target (#12247)

The logging streams now do almost no work when there is no output target for them.

For example, if LL_VERBOSE has no output targets, then `verbosestream << x` will return a StreamProxy with a null target. Any further `<<` operations applied to it will do nothing.

1 files changed, 175 insertions, 27 deletions

diff --git a/src/log.h b/src/log.h
index 6ed6b1fb7..5c6ba7d64 100644
--- a/src/log.h
+++ b/src/log.h
@@ -19,6 +19,7 @@ with this program; if not, write to the Free Software Foundation, Inc.,
 
 #pragma once
 
+#include <atomic>
 #include <map>
 #include <queue>
 #include <string>
@@ -28,6 +29,8 @@ with this program; if not, write to the Free Software Foundation, Inc.,
 #if !defined(_WIN32)  // POSIX
 	#include <unistd.h>
 #endif
+#include "util/basic_macros.h"
+#include "util/stream.h"
 #include "irrlichttypes.h"
 
 class ILogOutput;
@@ -39,6 +42,7 @@ enum LogLevel {
 	LL_ACTION,  // In-game actions
 	LL_INFO,
 	LL_VERBOSE,
+	LL_TRACE,
 	LL_MAX,
 };
 
@@ -67,12 +71,13 @@ public:
 	// Logs without a prefix
 	void logRaw(LogLevel lev, const std::string &text);
 
-	void setTraceEnabled(bool enable) { m_trace_enabled = enable; }
-	bool getTraceEnabled() { return m_trace_enabled; }
-
 	static LogLevel stringToLevel(const std::string &name);
 	static const std::string getLevelLabel(LogLevel lev);
 
+	bool hasOutput(LogLevel level) {
+		return m_has_outputs[level].load(std::memory_order_relaxed);
+	}
+
 	static LogColor color_mode;
 
 private:
@@ -84,6 +89,7 @@ private:
 	const std::string getThreadName();
 
 	std::vector<ILogOutput *> m_outputs[LL_MAX];
+	std::atomic<bool> m_has_outputs[LL_MAX];
 
 	// Should implement atomic loads and stores (even though it's only
 	// written to when one thread has access currently).
@@ -91,7 +97,6 @@ private:
 	volatile bool m_silenced_levels[LL_MAX];
 	std::map<std::thread::id, std::string> m_thread_names;
 	mutable std::mutex m_mutex;
-	bool m_trace_enabled;
 };
 
 class ILogOutput {
@@ -185,35 +190,178 @@ private:
 	Logger &m_logger;
 };
 
+#ifdef __ANDROID__
+class AndroidLogOutput : public ICombinedLogOutput {
+public:
+	void logRaw(LogLevel lev, const std::string &line);
+};
+#endif
 
-extern StreamLogOutput stdout_output;
-extern StreamLogOutput stderr_output;
-extern std::ostream null_stream;
+/*
+ * LogTarget
+ *
+ * This is the interface that sits between the LogStreams and the global logger.
+ * Primarily used to route streams to log levels, but could also enable other
+ * custom behavior.
+ *
+ */
+class LogTarget {
+public:
+	// Must be thread-safe. These can be called from any thread.
+	virtual bool hasOutput() = 0;
+	virtual void log(const std::string &buf) = 0;
+};
 
-extern std::ostream *dout_con_ptr;
-extern std::ostream *derr_con_ptr;
-extern std::ostream *derr_server_ptr;
 
-extern Logger g_logger;
+/*
+ * StreamProxy
+ *
+ * An ostream-like object that can proxy to a real ostream or do nothing,
+ * depending on how it is configured. See LogStream below.
+ *
+ */
+class StreamProxy {
+public:
+	StreamProxy(std::ostream *os) : m_os(os) { }
+
+	template<typename T>
+	StreamProxy& operator<<(T&& arg) {
+		if (m_os) {
+			*m_os << std::forward<T>(arg);
+		}
+		return *this;
+	}
 
-// Writes directly to all LL_NONE log outputs for g_logger with no prefix.
-extern std::ostream rawstream;
+	StreamProxy& operator<<(std::ostream& (*manip)(std::ostream&)) {
+		if (m_os) {
+			*m_os << manip;
+		}
+		return *this;
+	}
 
-extern std::ostream errorstream;
-extern std::ostream warningstream;
-extern std::ostream actionstream;
-extern std::ostream infostream;
-extern std::ostream verbosestream;
-extern std::ostream dstream;
+private:
+	std::ostream *m_os;
+};
 
-#define TRACEDO(x) do {               \
-	if (g_logger.getTraceEnabled()) { \
-		x;                            \
-	}                                 \
-} while (0)
 
-#define TRACESTREAM(x) TRACEDO(verbosestream x)
+/*
+ * LogStream
+ *
+ * The public interface for log streams (infostream, verbosestream, etc).
+ *
+ * LogStream minimizes the work done when a given stream is off. (meaning
+ * it has no output targets, so it goes to /dev/null)
+ *
+ * For example, consider:
+ *
+ *     verbosestream << "hello world" << 123 << std::endl;
+ *
+ * The compiler evaluates this as:
+ *
+ *   (((verbosestream << "hello world") << 123) << std::endl)
+ *      ^                            ^
+ *
+ * If `verbosestream` is on, the innermost expression (marked by ^) will return
+ * a StreamProxy that forwards to a real ostream, that feeds into the logger.
+ * However, if `verbosestream` is off, it will return a StreamProxy that does
+ * nothing on all later operations. Specifically, CPU time won't be wasted
+ * writing "hello world" and 123 into a buffer, or formatting the log entry.
+ *
+ * It is also possible to directly check if the stream is on/off:
+ *
+ *   if (verbosestream) {
+ *       auto data = ComputeExpensiveDataForTheLog();
+ *       verbosestream << data << endl;
+ *   }
+ *
+*/
 
-#define dout_con (*dout_con_ptr)
-#define derr_con (*derr_con_ptr)
+class LogStream {
+public:
+	LogStream() = delete;
+	DISABLE_CLASS_COPY(LogStream);
+
+	LogStream(LogTarget &target) :
+		m_target(target),
+		m_buffer(std::bind(&LogStream::internalFlush, this, std::placeholders::_1)),
+		m_dummy_buffer(),
+		m_stream(&m_buffer),
+		m_dummy_stream(&m_dummy_buffer),
+		m_proxy(&m_stream),
+		m_dummy_proxy(nullptr) { }
+
+	template<typename T>
+	StreamProxy& operator<<(T&& arg) {
+		StreamProxy& sp = m_target.hasOutput() ? m_proxy : m_dummy_proxy;
+		sp << std::forward<T>(arg);
+		return sp;
+	}
 
+	StreamProxy& operator<<(std::ostream& (*manip)(std::ostream&)) {
+		StreamProxy& sp = m_target.hasOutput() ? m_proxy : m_dummy_proxy;
+		sp << manip;
+		return sp;
+	}
+
+	operator bool() {
+		return m_target.hasOutput();
+	}
+
+	void internalFlush(const std::string &buf) {
+		m_target.log(buf);
+	}
+
+	operator std::ostream&() {
+		return m_target.hasOutput() ? m_stream : m_dummy_stream;
+	}
+
+private:
+	// 10 streams per thread x (256 + overhead) ~ 3K per thread
+	static const int BUFFER_LENGTH = 256;
+	LogTarget &m_target;
+	StringStreamBuffer<BUFFER_LENGTH> m_buffer;
+	DummyStreamBuffer m_dummy_buffer;
+	std::ostream m_stream;
+	std::ostream m_dummy_stream;
+	StreamProxy m_proxy;
+	StreamProxy m_dummy_proxy;
+
+};
+
+#ifdef __ANDROID__
+extern AndroidLogOutput stdout_output;
+extern AndroidLogOutput stderr_output;
+#else
+extern StreamLogOutput stdout_output;
+extern StreamLogOutput stderr_output;
+#endif
+
+extern Logger g_logger;
+
+/*
+ * By making the streams thread_local, each thread has its own
+ * private buffer. Two or more threads can write to the same stream
+ * simultaneously (lock-free), and there won't be any interference.
+ *
+ * The finished lines are sent to a LogTarget which is a global (not thread-local)
+ * object, and from there relayed to g_logger. The final writes are serialized
+ * by the mutex in g_logger.
+*/
+
+extern thread_local LogStream dstream;
+extern thread_local LogStream rawstream;  // Writes directly to all LL_NONE log outputs with no prefix.
+extern thread_local LogStream errorstream;
+extern thread_local LogStream warningstream;
+extern thread_local LogStream actionstream;
+extern thread_local LogStream infostream;
+extern thread_local LogStream verbosestream;
+extern thread_local LogStream tracestream;
+// TODO: Search/replace these with verbose/tracestream
+extern thread_local LogStream derr_con;
+extern thread_local LogStream dout_con;
+
+#define TRACESTREAM(x) do {	\
+	if (tracestream) { 	\
+		tracestream x;	\
+	}			\
+} while (0)