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.
This commit is contained in:
paradust7 2022-05-04 11:55:01 -07:00 committed by GitHub
parent ae7664597e
commit 0704ca0550
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
14 changed files with 336 additions and 192 deletions

@ -1468,7 +1468,8 @@ language (Language) enum ,be,bg,ca,cs,da,de,el,en,eo,es,et,eu,fi,fr,gd,gl,hu,i
# - action
# - info
# - verbose
debug_log_level (Debug log level) enum action ,none,error,warning,action,info,verbose
# - trace
debug_log_level (Debug log level) enum action ,none,error,warning,action,info,verbose,trace
# If the file size of debug.txt exceeds the number of megabytes specified in
# this setting when it is opened, the file is moved to debug.txt.1,
@ -1477,7 +1478,7 @@ debug_log_level (Debug log level) enum action ,none,error,warning,action,info,ve
debug_log_size_max (Debug log file size threshold) int 50
# Minimal level of logging to be written to chat.
chat_log_level (Chat log level) enum error ,none,error,warning,action,info,verbose
chat_log_level (Chat log level) enum error ,none,error,warning,action,info,verbose,trace
# Enable IPv6 support (for both client and server).
# Required for IPv6 connections to work at all.

@ -1768,7 +1768,8 @@
# - action
# - info
# - verbose
# type: enum values: , none, error, warning, action, info, verbose
# - trace
# type: enum values: , none, error, warning, action, info, verbose, trace
# debug_log_level = action
# If the file size of debug.txt exceeds the number of megabytes specified in
@ -1779,7 +1780,7 @@
# debug_log_size_max = 50
# Minimal level of logging to be written to chat.
# type: enum values: , none, error, warning, action, info, verbose
# type: enum values: , none, error, warning, action, info, verbose, trace
# chat_log_level = error
# Enable IPv6 support (for both client and server).

@ -1491,7 +1491,7 @@ bool Game::connectToServer(const GameStartData &start_data,
client->m_simple_singleplayer_mode = simple_singleplayer_mode;
infostream << "Connecting to server at ";
connect_address.print(&infostream);
connect_address.print(infostream);
infostream << std::endl;
client->connect(connect_address,

@ -116,7 +116,7 @@ RenderingEngine::RenderingEngine(IEventReceiver *receiver)
}
SIrrlichtCreationParameters params = SIrrlichtCreationParameters();
if (g_logger.getTraceEnabled())
if (tracestream)
params.LoggingLevel = irr::ELL_DEBUG;
params.DriverType = driverType;
params.WindowSize = core::dimension2d<u32>(screen_w, screen_h);

@ -35,43 +35,30 @@ with this program; if not, write to the Free Software Foundation, Inc.,
#include <cerrno>
#include <cstring>
const int BUFFER_LENGTH = 256;
class StringBuffer : public std::streambuf {
class LevelTarget : public LogTarget {
public:
StringBuffer() {
buffer_index = 0;
}
int overflow(int c);
virtual void flush(const std::string &buf) = 0;
std::streamsize xsputn(const char *s, std::streamsize n);
void push_back(char c);
private:
char buffer[BUFFER_LENGTH];
int buffer_index;
};
class LogBuffer : public StringBuffer {
public:
LogBuffer(Logger &logger, LogLevel lev) :
logger(logger),
level(lev)
LevelTarget(Logger &logger, LogLevel level, bool raw = false) :
m_logger(logger),
m_level(level),
m_raw(raw)
{}
void flush(const std::string &buffer);
virtual bool hasOutput() override {
return m_logger.hasOutput(m_level);
}
virtual void log(const std::string &buf) override {
if (!m_raw) {
m_logger.log(m_level, buf);
} else {
m_logger.logRaw(m_level, buf);
}
}
private:
Logger &logger;
LogLevel level;
};
class RawLogBuffer : public StringBuffer {
public:
void flush(const std::string &buffer);
Logger &m_logger;
LogLevel m_level;
bool m_raw;
};
////
@ -80,31 +67,33 @@ public:
Logger g_logger;
#ifdef __ANDROID__
AndroidLogOutput stdout_output;
AndroidLogOutput stderr_output;
#else
StreamLogOutput stdout_output(std::cout);
StreamLogOutput stderr_output(std::cerr);
std::ostream null_stream(NULL);
#endif
RawLogBuffer raw_buf;
LevelTarget none_target_raw(g_logger, LL_NONE, true);
LevelTarget none_target(g_logger, LL_NONE);
LevelTarget error_target(g_logger, LL_ERROR);
LevelTarget warning_target(g_logger, LL_WARNING);
LevelTarget action_target(g_logger, LL_ACTION);
LevelTarget info_target(g_logger, LL_INFO);
LevelTarget verbose_target(g_logger, LL_VERBOSE);
LevelTarget trace_target(g_logger, LL_TRACE);
LogBuffer none_buf(g_logger, LL_NONE);
LogBuffer error_buf(g_logger, LL_ERROR);
LogBuffer warning_buf(g_logger, LL_WARNING);
LogBuffer action_buf(g_logger, LL_ACTION);
LogBuffer info_buf(g_logger, LL_INFO);
LogBuffer verbose_buf(g_logger, LL_VERBOSE);
// Connection
std::ostream *dout_con_ptr = &null_stream;
std::ostream *derr_con_ptr = &verbosestream;
// Common streams
std::ostream rawstream(&raw_buf);
std::ostream dstream(&none_buf);
std::ostream errorstream(&error_buf);
std::ostream warningstream(&warning_buf);
std::ostream actionstream(&action_buf);
std::ostream infostream(&info_buf);
std::ostream verbosestream(&verbose_buf);
thread_local LogStream dstream(none_target);
thread_local LogStream rawstream(none_target_raw);
thread_local LogStream errorstream(error_target);
thread_local LogStream warningstream(warning_target);
thread_local LogStream actionstream(action_target);
thread_local LogStream infostream(info_target);
thread_local LogStream verbosestream(verbose_target);
thread_local LogStream tracestream(trace_target);
thread_local LogStream derr_con(verbose_target);
thread_local LogStream dout_con(trace_target);
// Android
#ifdef __ANDROID__
@ -118,29 +107,15 @@ static unsigned int g_level_to_android[] = {
//ANDROID_LOG_INFO,
ANDROID_LOG_DEBUG, // LL_INFO
ANDROID_LOG_VERBOSE, // LL_VERBOSE
ANDROID_LOG_VERBOSE, // LL_TRACE
};
class AndroidSystemLogOutput : public ICombinedLogOutput {
public:
AndroidSystemLogOutput()
{
g_logger.addOutput(this);
}
~AndroidSystemLogOutput()
{
g_logger.removeOutput(this);
}
void logRaw(LogLevel lev, const std::string &line)
{
void AndroidLogOutput::logRaw(LogLevel lev, const std::string &line) {
STATIC_ASSERT(ARRLEN(g_level_to_android) == LL_MAX,
mismatch_between_android_and_internal_loglevels);
__android_log_print(g_level_to_android[lev],
PROJECT_NAME_C, "%s", line.c_str());
}
};
AndroidSystemLogOutput g_android_log_output;
}
#endif
///////////////////////////////////////////////////////////////////////////////
@ -164,6 +139,8 @@ LogLevel Logger::stringToLevel(const std::string &name)
return LL_INFO;
else if (name == "verbose")
return LL_VERBOSE;
else if (name == "trace")
return LL_TRACE;
else
return LL_MAX;
}
@ -176,21 +153,26 @@ void Logger::addOutput(ILogOutput *out)
void Logger::addOutput(ILogOutput *out, LogLevel lev)
{
m_outputs[lev].push_back(out);
m_has_outputs[lev] = true;
}
void Logger::addOutputMasked(ILogOutput *out, LogLevelMask mask)
{
for (size_t i = 0; i < LL_MAX; i++) {
if (mask & LOGLEVEL_TO_MASKLEVEL(i))
if (mask & LOGLEVEL_TO_MASKLEVEL(i)) {
m_outputs[i].push_back(out);
m_has_outputs[i] = true;
}
}
}
void Logger::addOutputMaxLevel(ILogOutput *out, LogLevel lev)
{
assert(lev < LL_MAX);
for (size_t i = 0; i <= lev; i++)
for (size_t i = 0; i <= lev; i++) {
m_outputs[i].push_back(out);
m_has_outputs[i] = true;
}
}
LogLevelMask Logger::removeOutput(ILogOutput *out)
@ -203,6 +185,7 @@ LogLevelMask Logger::removeOutput(ILogOutput *out)
if (it != m_outputs[i].end()) {
ret_mask |= LOGLEVEL_TO_MASKLEVEL(i);
m_outputs[i].erase(it);
m_has_outputs[i] = !m_outputs[i].empty();
}
}
return ret_mask;
@ -236,6 +219,7 @@ const std::string Logger::getLevelLabel(LogLevel lev)
"ACTION",
"INFO",
"VERBOSE",
"TRACE",
};
assert(lev < LL_MAX && lev >= 0);
STATIC_ASSERT(ARRLEN(names) == LL_MAX,
@ -297,7 +281,6 @@ void Logger::logToOutputs(LogLevel lev, const std::string &combined,
m_outputs[lev][i]->log(lev, combined, time, thread_name, payload_text);
}
////
//// *LogOutput methods
////
@ -349,6 +332,7 @@ void StreamLogOutput::logRaw(LogLevel lev, const std::string &line)
m_stream << "\033[37m";
break;
case LL_VERBOSE:
case LL_TRACE:
// verbose is darker than info
m_stream << "\033[2m";
break;
@ -396,6 +380,7 @@ void LogOutputBuffer::logRaw(LogLevel lev, const std::string &line)
color = "\x1b(c@#BBB)";
break;
case LL_VERBOSE: // dark grey
case LL_TRACE:
color = "\x1b(c@#888)";
break;
default: break;
@ -404,47 +389,3 @@ void LogOutputBuffer::logRaw(LogLevel lev, const std::string &line)
m_buffer.push(color.append(line));
}
////
//// *Buffer methods
////
int StringBuffer::overflow(int c)
{
push_back(c);
return c;
}
std::streamsize StringBuffer::xsputn(const char *s, std::streamsize n)
{
for (int i = 0; i < n; ++i)
push_back(s[i]);
return n;
}
void StringBuffer::push_back(char c)
{
if (c == '\n' || c == '\r') {
if (buffer_index)
flush(std::string(buffer, buffer_index));
buffer_index = 0;
} else {
buffer[buffer_index++] = c;
if (buffer_index >= BUFFER_LENGTH) {
flush(std::string(buffer, buffer_index));
buffer_index = 0;
}
}
}
void LogBuffer::flush(const std::string &buffer)
{
logger.log(level, buffer);
}
void RawLogBuffer::flush(const std::string &buffer)
{
g_logger.logRaw(LL_NONE, buffer);
}

200
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
/*
* 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;
};
/*
* 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;
}
StreamProxy& operator<<(std::ostream& (*manip)(std::ostream&)) {
if (m_os) {
*m_os << manip;
}
return *this;
}
private:
std::ostream *m_os;
};
/*
* 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;
* }
*
*/
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;
extern std::ostream null_stream;
extern std::ostream *dout_con_ptr;
extern std::ostream *derr_con_ptr;
extern std::ostream *derr_server_ptr;
#endif
extern Logger g_logger;
// Writes directly to all LL_NONE log outputs for g_logger with no prefix.
extern std::ostream rawstream;
/*
* 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 std::ostream errorstream;
extern std::ostream warningstream;
extern std::ostream actionstream;
extern std::ostream infostream;
extern std::ostream verbosestream;
extern std::ostream dstream;
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 TRACEDO(x) do { \
if (g_logger.getTraceEnabled()) { \
x; \
#define TRACESTREAM(x) do { \
if (tracestream) { \
tracestream x; \
} \
} while (0)
#define TRACESTREAM(x) TRACEDO(verbosestream x)
#define dout_con (*dout_con_ptr)
#define derr_con (*derr_con_ptr)

@ -453,14 +453,6 @@ static bool setup_log_params(const Settings &cmd_args)
}
}
// If trace is enabled, enable logging of certain things
if (cmd_args.getFlag("trace")) {
dstream << _("Enabling trace level debug output") << std::endl;
g_logger.setTraceEnabled(true);
dout_con_ptr = &verbosestream; // This is somewhat old
socket_enable_debug_output = true; // Sockets doesn't use log.h
}
// In certain cases, output info level on stderr
if (cmd_args.getFlag("info") || cmd_args.getFlag("verbose") ||
cmd_args.getFlag("trace") || cmd_args.getFlag("speedtests"))
@ -470,6 +462,12 @@ static bool setup_log_params(const Settings &cmd_args)
if (cmd_args.getFlag("verbose") || cmd_args.getFlag("trace"))
g_logger.addOutput(&stderr_output, LL_VERBOSE);
if (cmd_args.getFlag("trace")) {
dstream << _("Enabling trace level debug output") << std::endl;
g_logger.addOutput(&stderr_output, LL_TRACE);
socket_enable_debug_output = true;
}
return true;
}
@ -599,7 +597,7 @@ static void init_log_streams(const Settings &cmd_args)
warningstream << "Deprecated use of debug_log_level with an "
"integer value; please update your configuration." << std::endl;
static const char *lev_name[] =
{"", "error", "action", "info", "verbose"};
{"", "error", "action", "info", "verbose", "trace"};
int lev_i = atoi(conf_loglev.c_str());
if (lev_i < 0 || lev_i >= (int)ARRLEN(lev_name)) {
warningstream << "Supplied invalid debug_log_level!"

@ -230,14 +230,14 @@ void Address::setPort(u16 port)
m_port = port;
}
void Address::print(std::ostream *s) const
void Address::print(std::ostream& s) const
{
if (m_addr_family == AF_INET6)
*s << "[" << serializeString() << "]:" << m_port;
s << "[" << serializeString() << "]:" << m_port;
else if (m_addr_family == AF_INET)
*s << serializeString() << ":" << m_port;
s << serializeString() << ":" << m_port;
else
*s << "(undefined)";
s << "(undefined)";
}
bool Address::isLocalhost() const

@ -59,7 +59,7 @@ public:
int getFamily() const { return m_addr_family; }
bool isIPv6() const { return m_addr_family == AF_INET6; }
bool isZero() const;
void print(std::ostream *s) const;
void print(std::ostream &s) const;
std::string serializeString() const;
bool isLocalhost() const;

@ -41,25 +41,14 @@ namespace con
/* defines used for debugging and profiling */
/******************************************************************************/
#ifdef NDEBUG
#define LOG(a) a
#define PROFILE(a)
#else
#if 0
/* this mutex is used to achieve log message consistency */
std::mutex log_message_mutex;
#define LOG(a) \
{ \
MutexAutoLock loglock(log_message_mutex); \
a; \
}
#else
// Prevent deadlocks until a solution is found after 5.2.0 (TODO)
#define LOG(a) a
#endif
#define PROFILE(a) a
#endif
// TODO: Clean this up.
#define LOG(a) a
#define PING_TIMEOUT 5.0
u16 BufferedPacket::getSeqnum() const

@ -32,22 +32,18 @@ namespace con
/* defines used for debugging and profiling */
/******************************************************************************/
#ifdef NDEBUG
#define LOG(a) a
#define PROFILE(a)
#undef DEBUG_CONNECTION_KBPS
#else
/* this mutex is used to achieve log message consistency */
std::mutex log_conthread_mutex;
#define LOG(a) \
{ \
MutexAutoLock loglock(log_conthread_mutex); \
a; \
}
#define PROFILE(a) a
//#define DEBUG_CONNECTION_KBPS
#undef DEBUG_CONNECTION_KBPS
#endif
// TODO: Clean this up.
#define LOG(a) a
#define WINDOW_SIZE 5
static session_t readPeerId(const u8 *packetdata)

@ -198,7 +198,7 @@ void UDPSocket::Send(const Address &destination, const void *data, int size)
if (socket_enable_debug_output) {
// Print packet destination and size
dstream << (int)m_handle << " -> ";
destination.print(&dstream);
destination.print(dstream);
dstream << ", size=" << size;
// Print packet contents
@ -295,7 +295,7 @@ int UDPSocket::Receive(Address &sender, void *data, int size)
if (socket_enable_debug_output) {
// Print packet sender and size
dstream << (int)m_handle << " <- ";
sender.print(&dstream);
sender.print(dstream);
dstream << ", size=" << received;
// Print packet contents

@ -525,7 +525,7 @@ void Server::start()
actionstream << "World at [" << m_path_world << "]" << std::endl;
actionstream << "Server for gameid=\"" << m_gamespec.id
<< "\" listening on ";
m_bind_addr.print(&actionstream);
m_bind_addr.print(actionstream);
actionstream << "." << std::endl;
}

70
src/util/stream.h Normal file

@ -0,0 +1,70 @@
/*
Minetest
Copyright (C) 2022 Minetest Authors
This program is free software; you can redistribute it and/or modify
it under the terms of the GNU Lesser General Public License as published by
the Free Software Foundation; either version 2.1 of the License, or
(at your option) any later version.
This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
GNU Lesser General Public License for more details.
You should have received a copy of the GNU Lesser General Public License along
with this program; if not, write to the Free Software Foundation, Inc.,
51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
*/
#pragma once
#include <iostream>
#include <string>
#include <functional>
template<int BufferLength, typename Emitter = std::function<void(const std::string &)> >
class StringStreamBuffer : public std::streambuf {
public:
StringStreamBuffer(Emitter emitter) : m_emitter(emitter) {
buffer_index = 0;
}
int overflow(int c) {
push_back(c);
return c;
}
void push_back(char c) {
if (c == '\n' || c == '\r') {
if (buffer_index)
m_emitter(std::string(buffer, buffer_index));
buffer_index = 0;
} else {
buffer[buffer_index++] = c;
if (buffer_index >= BufferLength) {
m_emitter(std::string(buffer, buffer_index));
buffer_index = 0;
}
}
}
std::streamsize xsputn(const char *s, std::streamsize n) {
for (int i = 0; i < n; ++i)
push_back(s[i]);
return n;
}
private:
Emitter m_emitter;
char buffer[BufferLength];
int buffer_index;
};
class DummyStreamBuffer : public std::streambuf {
int overflow(int c) {
return c;
}
std::streamsize xsputn(const char *s, std::streamsize n) {
return n;
}
};