The design that you claim "works" comes with a caveat: it works extremely poorly.
You might not have noticed it when logging is set to a low level or when only one or two threads do the majority of logging. The threads that log infrequently still stall for many orders of magnitude longer than necessary. A simple logger should be able to saturate the disk while streaming data from multiple threads.
When writing any multithreaded code that needs to serialize access to resources, the duration of each serialized or atomic access should be minimal. The implementation of Logger::log
is a textbook case of doing it exactly the opposite of how it should be done.
The Cardinal Rule of Locking
Don't hold locks for anything but very simple manipulations of variables you have under full control. Basically: if you do any work while holding a lock, it should be trivial and touch small numbers of cachelines. Ideally you should be able to articulate roughly how many. I/O, memory allocation, syscalls (crossing user-kernel boundary), accessing many pages of memory, and similar are performance killers.
Let's now look at the "working" implementation:
void Logger::log( const char* text, LoggerType type ) {
if ( nullptr = spLogger_ ) {
// output error message
return;
}
Hopefully that error message is only output once, perhaps with a count of how many times this call has failed. It's not a good way to start your day when the application you're using is dumping thousands of error messages to console or raises popups until it runs out of GDI or X handles...
BlockThread blockThread( spLogger->criticalSection_ );
Everything from now on is indeed critical and shouldn't be done unless it really is critical.
std::ostringstream stream;
// setup logger's text formatting
// get the date and time
// push the date and time into the stream
// push the text message into the stream
// print stream to console
This allocates memory many times. Each time an allocation is performed, a global heap allocator lock is obtained - in some allocators it won't be for every allocation, but will still happen. That means that you're paying the cost of serializing access repeatedly for the same small chunk of code.
This code also does kernel calls galore. There's no reason to serialize it, because no shared resources are used. If anything, that BlockThread
should be here, not many lines earlier.
try {
Exceptions are fine as long as they are thrown rarely. In C++, exception handling may allocate memory, perhaps many times in some corner cases.
Since you throw in the critical section, anytime an exception is thrown the threads that attempt to log revert to single-core operation: until the exception is processed, the critical section is held locked.
TextFileWriter file (spLogger_->filename_, true, false );
A file is opened every time something is logged... Have you tried how long will it take to log a million empty lines? After all, it's just a megabyte or two of data. Should take maybe a couple milliseconds at worst, typically way better than that... But here, this won't be the case! On a network file system, this may take minutes!
file.write( stream.str() );
Bad idea. stream.str()
copies the string. This API is basically broken and you need to use lower level methods of the stream buffer to do this efficiently. See void LogSource::write(std::streambuf* buf)
further below for a better implementation.
} catch( ... ) {
// output error message failed to write to file.
Again: Hopefully this message is output only once for any given file. This sort of "dump the errors on the user" is bad UX. What can the user do if she sees thousands of messages scrolling past, with the application unresponsive?
OK, so we know that this is totally not the way to do it :)
An Example
A complete example follows, albeit not always in source file order.
Let's start with a counterexample to the critique given - the method that actually logs to the file.
LogSink::run() Implementation
void LogSink::run()
{
using std::swap, std::next;
bool stop = false, wasBusy = true;
std::string filename;
while (!stop)
{
// Process the global state and newly arrived log sources
{
/*l*/ auto l = locked();
/*l*/ filename = l->filename;
/*l*/ swap(l->newSources, this->newSources);
/*l*/
/*l*/ if (!wasBusy && this->newSources.empty() && !l->stopWorker)
/*l*/ condVar.wait(l.lock());
/*l*/
/*l*/ stop = l->stopWorker;
}
// Record the newly created sources
for (auto &newSource : this->newSources)
sources.emplace_back(std::move(newSource));
this->newSources.clear();
// Write out the data from all the sources to the file
wasBusy = false;
if (filename.empty())
continue; // no writing if the filename is not set
ofs.open(filename, std::ios_base::app);
for (auto it = sources.begin(); it != sources.end(); )
{
/*l*/ auto l = (*it)->locked();
/*l*/ auto& readOnly = l->readOnly;
/*l*/ bool const finished = l->finished;
/*l*/ if (!l->writeOnly.empty())
/*l*/ swap(l->writeOnly, l->readOnly);
/*l*/ l.unlock();
if (!readOnly.empty())
{
ofs.write( readOnly.data(), readOnly.size() );
readOnly.clear();
wasBusy = true;
}
if (finished)
it = sources.erase(it);
else
it = next(it);
}
ofs.close();
}
}
First, let's mention two fundamental concepts in this design. Shown above is a part of the log sink: where the logged messages are dumped to be processed. The messages come from threads that do actual work and need to log things - those are the log sources.
The LogSink::run
method runs in a dedicated worker thread, so that file accesses are essentially invisible to the threads that do the logging - by the virtue of minimizing lock contention.
I've marked the sections of code that hold a lock with '/*l*/
' in the margin. Let's analyze why this has a chance of performing decently.
// Process the global state and newly arrived log sources
{
/*l*/ auto l = locked(); <- 1
/*l*/ filename = l->filename; <- 2
/*l*/ swap(l->newSources, this->newSources); <- 3
/*l*/
/*l*/ if (!wasBusy && this->newSources.empty() && !l->stopWorker) <- 4
condVar.wait(l.lock()); <- 5
/*l*/
/*l*/ stop = l->stopWorker; <- 6
} <- 7
This part holds a global lock on the event sink's state; the state is accessible via l->
.
The lock was acquired with no to very little contention. This will usually be the case, since the lock is held for a small fraction of a μs by the sink thread.
The contention can only take place when other threads:
create a log source, on the first use of the logger from given thread, and
destroy a log source, when a thread that had previously used a logger terminates
These two events happen rarely, and themselves are not low-cost operations, so increasing their overhead just slightly is not going to even be measurable. Well designed applications create and destroy threads very sparingly.
The filename is copied. This copies a few cachelines of data but doesn't allocate (except once initially). The cost of this operation is essentially zero, since the local filename
variable is not accessed until later, and thus the operations performed on it have every reason to be parallelized by the fancy execution machinery of modern out-of-order CPUs.
Two std::vector
s are swapped: l->newSources
with this->newSources
. l->newSources
are protected by the lock and would be accessed from other threads by the log sources, the ones in this
object are only processed from the log sink's thread.
The string copy and vector swapping is extremely fast: literally a dozen cachelines worth of data are moved around.
If the last iteration of the loop had no work, i.e. didn't write anything out (!wasBusy
), and there were no new log sources added (newSources.empty()
), and the log sink wasn't finishing work (!l->stopWorker
), then the worker thread goes to sleep waiting on a condition variable that will be set by the log sources.
When is entered std::condition_variable::wait
, the lock on the state view l
is removed. As soon as the condition is signaled and the thread resumes, the lock is reacquired. I.e. "inside" of condVar.wait
the lock is temporarily suspended, but outside of it the lock is present.
As soon as the thread resumes, the local bool stop
variable is updated from the locked sink state l->
. This takes advantage of the lock being already held, so we get the newest state of the l->stopWorker
flag.
The lock holder l
is destroyed at the end of scope, and the lock is released.
Next comes some code that runs with no locks held (almost).
// Record the newly created sources
for (auto &newSource : this->newSources) <- 1
sources.emplace_back(std::move(newSource)); <- 2
this->newSources.clear(); <- 3
// Write out the data from all the sources to the file
wasBusy = false; <- 4
if (filename.empty()) <- 5
continue; // no writing if the filename is not set
ofs.open(filename, std::ios_base::app); <- 6
The log sources are moved from the temporary array newSources
to the work list [this->]sources
that holds all the log sources that need to be processed by the log sink. Note that newSources
is not a local variable: it's a member of LogSink
, and thus doesn't need to reallocate memory.
An extraordinary cost may be due to a potential atomic memory accesses in the moving constructor std::shared_ptr::shared_ptr(std::shared_ptr &&)
. That is usually implementation-dependent, but all recent ones behave rather well. This is a hardware-mediated cacheline-based exclusive access done with a special machine opcode, not a syscall.
In decent implementations of C++, std::vector::capacity
survives the clear()
. After a few initial allocations at the startup of the logger, these three lines will not be allocating nor deallocating.
The flag that indicates whether any work was done when writing to the file is cleared (wasBusy=false
).
If the filename is not set, the loop short-circuits and likely will wait on the condition variable. Any changes to the log sink's state made from other threads always signal the condition variable, so that the sink thread will resume and pick up any changes made - such as, for example setting the filename (see one paragraph below the next one).
The file is opened for appending. This may allocate buffers within std::basic_filebuf
. Since the entire stream and its buffer are members of LogSink
, no allocations are made after initial startup. Still, the cost of a userspace-to-kernel transition is not to be discounted, never mind the tens of thousands of instructions needed, in the best case, to process a file opening request, assuming the relevant filesystem pages are in memory, decompressed, etc. Modern kernels perform much of this processing in kernel threads, so the userspace thread is likely to block and go to sleep until the file is opened.
Now an intermission: we've mentioned setting the filename just two paragraphs ago. Let's see how that's done, since this pattern recurs anytime the state of the log sink is modified in any way from other threads:
void LogSink::setFilename(std::string_view filename)
{
if (!filename.empty()) <- 1
{
/*l*/ auto l = locked(); <- 2
/*l*/ l->filename = filename; <- 3
/*l*/ wakeUp(l); <- 4
}
}
std::string_view
is a C++-17 class that conveniently wraps const char *, size_t
. It is very flexible: it efficiently accepts string literals, std::string
, and the various string views produced by picking out fragments of strings. A highly recommended class wherever you previously had const std::string &
. It is a value type and should be always passed into functions by value.
An empty filename is ignored. This is a "cop out": perhaps not the best design, but for now it can do. After all, this is just an example that would need to be adapted to application requirements.
LogSink::locked
is used to obtain a locked view of the log sink's state.
The filename is updated within the locked view. A memory allocation may be done here - but only if the new filename is larger than the previous one. The cost of copying the filename characters is essentially nil, since those characters are used hundreds of clock cycles later, and thus it can be parallelized at a hardware level by fancypants CPUs.
The LogSink::wakeUp
is used on the locked view. This unlocks the view and signals the LogSink::condVar
condition variable, thus waking up the worker thread and resuming LogSink::run
if it wasn't running already.
Our discussion is now back to LogSink::run()
, resuming right after the output stream LogSink::ofs
has been opened.
We've been looking at the log sink this whole time, now we need to introduce the log sources. There's one log source per any thread that invokes the logging functions. It's created on demand, and is co-owned by the log sink and the source thread. Once the thread terminates, the only owner left is the log sink, and it then discards the source.
The following is a loop that iterates all log sources, and writes out their data to the output file (via LogStream::ofs
).
for (auto it = sources.begin(); it != sources.end(); )
{
/*l*/ auto l = (*it)->locked(); <- 1
/*l*/ auto& readOnly = l->readOnly; <- 2
/*l*/ bool const finished = l->finished; <- 3
/*l*/ if (!l->writeOnly.empty()) <- 4
/*l*/ swap(l->writeOnly, l->readOnly);
/*l*/ l.unlock(); <- 5
Just as the log sink state could be locked, so can be the log source state. l->
accesses the currently iterated source's state under the lock.
The contention for this lock is low, since:
there is only one other thread that uses this lock: the source thread,
the source thread does a minimal amount of work under the lock: a very fast swap of two strings that takes a fraction of a microsecond.
Each source contains two string members: writeOnly
and readOnly
. As their names imply, the writeOnly
string is only ever written within the thread the source is in, whereas the readOnly
string is only ever read in the thread the sink is in.
The writeOnly
string is where every message logged in a given string is appended to, until the log sink comes around to dumping it to the file.
The finished
state of the source is captured in a local variable.
If the writeOnly
string is not empty, we swap the writeOnly
and readOnly
strings: that's how the sink gets hold of the data written by the log source.
Now we're done with the log source - we can unlock its state.
The rest of the per-source work is done without holding locks:
if (!readOnly.empty()) <- 1
{
ofs.write( readOnly.data(), readOnly.size() ); <- 2
readOnly.clear();
wasBusy = true; <- 3
}
if (finished) <- 4
it = sources.erase(it);
else
it = next(it);
}
The data written by the source is now in the readOnly
string. We only need to deal with it if the string is not empty.
The data is written to the output file stream ofs
. The string is then cleared. That typically preserves the memory allocated by the string, so that no reallocations will be necessary.
A flag is set to indicate that we did some work in this iteration through the outer loop.
Finally, we have to advance to the next source. If the source has finished (i.e. its thread is done), the source gets erased. std::vector::erase
returns the iterator to the next element. Otherwise, std::next(iterator)
is used for the same purpose. Instead of std::next
, we could also have used it++
.
ofs.close(); <- 1
} <- 2
- Now the log file is closed, and
- The outer loop continues for the next iteration.
A short diversion into the LogSource
: how do we add data to the writeOnly
string? Like this:
void LogSource::write(std::string_view str) <- 1
{
auto l = locked(); <- 2
auto const destPos = l->writeOnly.size(); <- 3
l->writeOnly.reserve(destPos + str.size());
std::copy(str.begin(), str.end(), std::back_inserter(l->writeOnly)); <- 4
wakeUpSink(l); <- 5
}
This write
method takes strings in general: std::string_view
will accept const std::string &
, const char *
, and others.
Lock the source, so that the sink won't be able to modify the writeOnly
while we need it.
Get the current size of the write "buffer" string, and reserve enough additional space to fit the string being written.
Copy the string to be written to the back of the write buffer.
Wake up the sink, so that it has a chance to notice that there is some work to do.
The Scalable Performance of LogSink
The design presented above has a very important scalability aspect: it automatically reduces overheads the busier it gets.
That means that when there's little work to do, the log file will be opened and closed perhaps even once for every message written, and the write sizes are minuscule. This has relatively large overhead, but is appropriate when there's not much pressure on the logger. This is what the original implementation in the question was doing always.
The problem is that this high-overhead approach is not appropriate when there's lots of logging messages to write out, whereas it is definitely the right thing to do when there's not much work. Instead, the relative overhead should be reduced to keep up with the demand on the sink.
When the logger is "inundanted" with data, the overheads get automatically reduced:
The file is only closed when all available work from all sinks has been written out.
The write requests keep getting larger as the amount of work available grows. This reduces the relative overhead of file writing system calls.
The contention for the per-source lock is almost nil, since the sink is mostly busy writing the data out to the file. It only locks the source to swap the writeOnly
buffer with the readOnly
buffer. The relative time spent holding the source lock is minuscule compared to the time spent writing.
Furthermore, each source thread has its own dedicated lock, increasing the number of threads does not raise contention on this often-used lock.
The contention for the per-sink lock is also negligible, since it can only happen during a very short section of the sink loop, and only when it coincides with first use of the logger in a newly created thread, or with thread termination. In well designed applications, thread creation and destruction is very rare - and in any case it's such an expensive operation, that adding comparatively minuscule overhead to it has no effect.
The Interface
The Logger
class is the singleton sink. This particular implementation shares ownership of the sink, so any number of Logger
instances can exist, but they all share the same LogSink
. That class is not copyable.
In addition to the static log
methods you suggested, there's also an argument-less method log()
that returns a LogStream
, which works just like any other output stream. E.g. you can do Logger::log() << 1 << 2 << '\n'
.
// log.hpp
#pragma once
#include <iostream>
#include <memory>
#include <string_view>
class Logger final
{
public:
explicit Logger(std::string_view filename);
~Logger();
Logger(const Logger&) = delete;
Logger& operator=(const Logger&) = delete;
static void log(std::ostringstream *stream);
static void log(const std::ostringstream &stream);
static void log(std::string_view text);
static inline class LogStream log();
private:
std::shared_ptr<class LogSink> d;
};
class LogStream final
{
public:
LogStream();
~LogStream();
template <typename T>
friend const LogStream& operator<<(const LogStream& ls, const T& val)
{
ls.stream << val;
return ls;
}
operator std::ostream&() { return stream; }
private:
class LogSource* source;
std::ostream& stream;
};
inline LogStream Logger::log() { return {}; }
The Implementation
First, the declarations of the global and per-thread state, as well as declarations of the implementation classes:
// log.cpp
#include "log.hpp"
#include <cassert>
#include <condition_variable>
#include <fstream>
#include <mutex>
#include <sstream>
#include <vector>
//
// Durable Resources
//
static std::mutex globalMutex;
static std::shared_ptr<LogSink> globalSink;
class LogSourceOwner
{
class LogSource *source = {};
public:
LogSource* getOrMake();
~LogSourceOwner();
}
static thread_local localSource;
//
// Helpers
//
class LockedViewBase
{
std::unique_lock<std::mutex> _lock;
protected:
void* data;
LockedViewBase(void* data, std::mutex& mutex) : _lock(mutex), data(data) {}
public:
void unlock() {
data = nullptr;
_lock.unlock();
}
auto& lock() { return _lock; }
};
template <typename T>
class LockedView : public LockedViewBase
{
public:
LockedView(T* data, std::mutex& mutex) : LockedViewBase(data, mutex) {}
T* operator->() const { return reinterpret_cast<T*>(data); }
};
//
// LogSink Declaration
//
struct LogSinkState
{
bool stopWorker = false;
std::vector<std::shared_ptr<LogSource>> newSources;
std::string filename;
};
class LogSink : public std::enable_shared_from_this<LogSink>
{
public:
static std::shared_ptr<LogSink> getOrMake(std::string_view filename);
explicit LogSink(std::string_view filename);
void finish();
void setFilename(std::string_view filename);
void wakeUp(LockedViewBase& l) {
l.unlock();
condVar.notify_one();
}
LogSource* createSource();
private:
LogSinkState state;
std::condition_variable condVar;
std::ofstream ofs;
std::vector<std::shared_ptr<LogSource>> newSources, sources;
std::thread worker;
void run();
auto locked() { return LockedView{&state, globalMutex}; }
};
//
// LogSource Declaration
//
struct LogSourceState
{
bool finished = false;
std::string writeOnly, readOnly;
};
class LogSource
{
public:
static LogSource* getOrMake() { return localSource.getOrMake(); }
explicit LogSource(std::shared_ptr<LogSink> logger) : logger(std::move(logger)) {}
auto locked() { return LockedView{&state, sourceMutex}; }
void wakeUpSink(LockedViewBase& l) { logger->wakeUp(l); }
std::ostream &msgStream() { return message; }
void write(std::string_view str);
void write(std::streambuf *buf);
char* allocWriteBuf(std::size_t size, LockedView<LogSourceState>& l);
private:
std::shared_ptr<LogSink> logger;
std::ostringstream message;
std::mutex sourceMutex;
LogSourceState state;
};
LogSink Implementation
//
// LogSink
//
LogSource* LogSink::createSource()
{
auto source = std::make_shared<LogSource>(shared_from_this());
locked()->newSources.push_back(source);
return source.get();
}
std::shared_ptr<LogSink> LogSink::getOrMake(std::string_view filename = {})
{
std::unique_lock lock(globalMutex);
if (!globalSink)
globalSink = std::make_shared<LogSink>(filename);
else
globalSink->setFilename(filename);
return globalSink;
}
LogSink::LogSink(std::string_view filename)
{
state.filename = filename;
worker = std::thread(&LogSink::run, this);
}
void LogSink::setFilename(std::string_view filename)
{
if (!filename.empty())
{
auto l = locked();
l->filename = filename;
wakeUp(l);
}
}
void LogSink::finish()
{
auto l = locked();
l->stopWorker = true;
wakeUp(l);
worker.join();
}
// LogSink::run() is here
LogSource implementation
//
// Log Source
//
LogSource* LogSourceOwner::getOrMake()
{
if (!source)
source = LogSink::getOrMake()->createSource();
return source;
}
LogSourceOwner::~LogSourceOwner()
{
if (source) {
auto l = source->locked();
l->finished = true;
source->wakeUpSink(l);
}
source = nullptr;
}
void LogSource::write(std::string_view str)
{
auto l = locked();
auto const destPos = l->writeOnly.size();
l->writeOnly.reserve(destPos + str.size());
std::copy(str.begin(), str.end(), std::back_inserter(l->writeOnly));
wakeUpSink(l);
}
void LogSource::write(std::streambuf* buf)
{
if (buf)
{
// note: buf->in_avail() does not do what we want
auto size = std::size_t(buf->pubseekoff(0, std::ios_base::cur, std::ios_base::out));
{
auto l = locked();
buf->sgetn(allocWriteBuf(size, l), size);
wakeUpSink(l);
}
buf->pubseekpos(0);
}
}
char* LogSource::allocWriteBuf(std::size_t size, LockedView<LogSourceState>& l)
{
const auto destPos = std::size_t(l->writeOnly.size());
l->writeOnly.resize(destPos + size);
return l->writeOnly.data() + destPos;
}
Public API Implementation
//
// Public API
//
LogStream::LogStream() :
source(LogSource::getOrMake()),
stream(source->msgStream())
{}
LogStream::~LogStream()
{
source->write(stream.rdbuf());
stream.flush();
stream.clear();
}
Logger::Logger(std::string_view filename) :
d(LogSink::getOrMake(filename))
{}
Logger::~Logger()
{
d->finish();
{
std::unique_lock lock(globalMutex);
globalSink.reset();
d.reset();
}
}
void Logger::log(std::ostringstream *stream)
{
if (stream && stream->rdbuf())
{
LogSource::getOrMake()->write(stream->rdbuf());
stream->rdbuf()->pubsync();
stream->clear();
}
}
void Logger::log(const std::ostringstream& stream)
{
#if __cplusplus >= 202002L
Logger::log(stream.view());
#else
if (stream.rdbuf())
{
LogSource::getOrMake()->write(stream.rdbuf());
stream.rdbuf()->pubsync();
}
#endif
}
void Logger::log(std::string_view text)
{
LogSource::getOrMake()->write(text);
}
Demo
#include <thread>
#include "log.hpp"
int main()
{
Logger logger("log.txt");
std::thread t1([]{ Logger::log() << "tt1\n"; });
std::thread t2([]{ Logger::log() << "tt2\n"; });
Logger::log("line l1\n");
Logger::log("line l2\n");
t1.join();
t2.join();
return 0;
}
First, a logger (log sink) is created, then two threads that log to it, as well as some logging is done from the main thread.
TODOs
Even though this is an example, somewhat contrived for brevity, it's not far from a minimal viable logger module. At minimum, the following features would need to be implemented to make it really useful:
Policy of dealing with the log source buffers growing past some maximum size:
- a temporary reduction of logging level for the given source, to reduce the amount of output, if logging levels are in use,
- discarding the buffer, or parts of it (e.g. reduction by half),
- stopping the thread until the logger catches up.
Handling of timestamps: the system calls typically used to obtain time and date are relatively expensive. There are many ways of dealing with that, for example:
capture the date-time using usual API, then use a hardware (CPU instruction) high resolution performance timer to add offsets to that, and refresh the date-time say once a minute,
capture the date-time into a global atomic variable (e.g. Unix epoch in ms into a uint64_t
) in the sink thread, e.g. once per each source while in the source loop, and consume it in the source threads; this has an additional atomic memory access cost roughly equal to the uncontested mutex lock.
A better string formatting library, std::format
in C++20 is a natural choice and performs very well, or use fmtlib/fmt for pre-C++20 code (std::format
was essentially adopted from fmtlib/fmt).
Platform-specific asynchronous file writing, i.e. use asynchronous file I/O if such is available, and have the per-sink buffers be page-aligned kernel-shared buffers, so that the logged data is not copied from the userspace to the kernel.