3
\$\begingroup\$

I have an older class that I am working on and I'm updating it to remove "Windows" specific code. It had some "Thread Protection Code" that used CRITICAL_SECTION. I'm in the process of changing the use of CRITICAL_SECTION to use std::mutex and std::lock_guard. One thing to take note of is that my class does have static functions and this class is of a singleton type.

This is what my old code would have looked like.

-Logger.h-

#pragma once

#include "Singleton.h"

class Logger final : public Singleton {
public: 
    // enum here

private:
    // private variables not of concern

    CRITICAL_SECTION criticalSection_;

public:
    explicit Logger( const std::string& filename );
    virtual ~Logger();

    static void log( const std::string& text, LoggerType type );
    static void log( const std::ostringstream& stream, LoggerType type );
    static void log( const char* text, LoggerType type )
};

-Logger.cpp-

#include "Logger.h"

#include "BlockThread.h" // old class that would block threads - replacing with mutex lock_guard

#include "TextFileWriter.h" // file handler the Logger uses to write text files

// since this is a singleton type class as I only want a single logger per
// application run; here I use a static pointer to this class, the reason
// the log functions are static to begin with.
static Logger* spLogger_ = nullptr;

Logger::Logger( const std::string& filename ) :
Singleton( LOGGER ) {  // Base class takes an enum type of Singleton
    // variable initializations
    // ...
    // ------------------------

    InitializeCriticalSection( &criticalSection_ );
    BlockThread blockThread( criticalSection ); // Enter Critical Section

    // Start the log file
    TextFileWriter file( filename_, false, false ); //

    spLogger_ = this;
}

Logger::~Logger() {
    spLogger_ = nullptr;

    DeleteCriticalSection( &criticalSection_ );
}

void Logger::log( const std::string& text, LoggerType type ) {
    log( text.c_str(), type );
}

void Logger::log( const std::ostringstream& stream, LoggerType type ) {
    log( stream.str().c_str(), type );
}

void Logger::log( const char* text, LoggerType type ) {
    if ( nullptr = spLogger_ ) {
        // output error message
        return; 
    }

    BlockThread blockThread( spLogger->criticalSection_ ); // Enter Critical Section

    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

    try {
        TextFileWriter file (spLogger_->filename_, true, false );
        file.write( stream.str() );
    } catch( ... ) {
        // output error message failed to write to file.
    }
}

If you need to see the BlockThread class I'll show it here just incase...

-BlockThread.h-

#pragma once

class BlockThread final {
private:
    CRITICAL_SECTION* criticalSection_;

public:
    explicit BlockThread( CRITICAL_SECTION& criticalSection );
    ~BlockThread();
};

-BlockThread.cpp-

#include "BlockThread.h"

BlockThread::BlockThread( CRITICAL_SECTION& criticalSection ) {
    criticalSection_ = &criticalSection;
    EnterCriticalSection( criticalSection_ );
}

BlockThread::~BlockThread() {
    LeaveCriticalSection( criticalSection_ );
}

This was how my old classes were set up.


This is my attempt to remove BlockThread class and the CRITICAL_SECTION and its related functions by replacing them with std::mutex and std::lock_guard

-Logger.h-

#pragma once

#include "Singleton.h"

#include <mutex> // added this for mutex

class Logger final : public Singleton {
public:
    // public enum

private:
    // private members

    // CRITICAL_SECTION
    static std::mutex critical_;

public:
    // constructor, destructor and log function declarations same as above

};

-Logger.cpp-

#include "Logger.h"

static Logger* spLogger_ = nullptr;
std::mutex Logger::critical_{};

Logger::Logger( const std::string& filename ) {
    // init variables

    // InitializeCriticalSection( &criticalSection_ )
    // BlockThread blockThread( criticalSection_ );
    std::lock_guard<std::mutex> lock(critical_ );

    TextFileWriter file( filename, false, false );

    spLogger_ = this;
}

Logger::~Logger() {
    spLogger_ = nullptr;

    // DeleteCriticalSection( &criticalSection_ );

    // Left empty don't think I have to do anything since `lock_guard`
    // is destroyed once it leaves its scope...
}

// skip the first two log functions no difference here...

void Logger::log( const char* text, LoggerType type ) {
    // check if spLogger_ is null if so print error message & return

    // BlockThread blockThread( spLogger_->criticalSection_ ); // Enter Critical Section

    std::lock_guard<std::mutex> lock( spLogger_->criticalSection_ );

    // text formatting, date-time and message

    // print stream to console

    // try catch block same as above.
}

There's a set of questions that are sort of related; that's why I feel they are all important in this situation...

What I would like to know:

  • Is the replacement of my original CRITICAL_SECTION it's related functions and my original BlockThread class with std::mutex and std::lock_guard correct?
  • Will this behave in the same manner or fashion?
  • If not what would be the correct way to replace them as I'm not real familiar with std::mutex & std::lock_guard? - I'm trying to get a better grasp and understanding of how to use them properly.
  • Is there anything that I am missing, any corner cases or code smell such as possible data races, dead lock, or live lock?
  • -Note- I'm not really concerned with the commented out code as I know the original class works fine; I'm mainly concerned where I made the replacements.
  • What can I do to make this code follow modern C++ standards; to make it portable, cross-platform capable etc.

-Edit-

One of the major motivations for writing this question is that I have other classes in a decent size library that had previously used CRITICAL_SECTION its related functions and my old BlockThread class. Once I know how to properly replace them with std::mutex, std::lock_guard or any of their variations... Then I should easily be able to replace all thread safety features in my library.

\$\endgroup\$
5
\$\begingroup\$

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->.

  1. 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.

  2. 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.

  3. Two std::vectors 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.

  4. 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.

  5. 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.

  6. 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.

  7. 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
  1. 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.

  2. 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.

  3. 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.

  4. The flag that indicates whether any work was done when writing to the file is cleared (wasBusy=false).

  5. 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).

  6. 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.

  1. 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.

  2. LogSink::locked is used to obtain a locked view of the log sink's state.

  3. 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.

  4. 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
  1. 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.

  2. 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.

  3. The finished state of the source is captured in a local variable.

  4. 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.

  5. 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);
      }
  1. 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.

  2. 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.

  3. A flag is set to indicate that we did some work in this iteration through the outer loop.

  4. 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
  1. Now the log file is closed, and
  2. 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
}
  1. This write method takes strings in general: std::string_view will accept const std::string &, const char *, and others.

  2. Lock the source, so that the sink won't be able to modify the writeOnly while we need it.

  3. Get the current size of the write "buffer" string, and reserve enough additional space to fit the string being written.

  4. Copy the string to be written to the back of the write buffer.

  5. 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:

  1. The file is only closed when all available work from all sinks has been written out.

  2. The write requests keep getting larger as the amount of work available grows. This reduces the relative overhead of file writing system calls.

  3. 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.

  4. 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:

  1. 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.
  2. 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.

  3. 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).

  4. 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.

\$\endgroup\$
2
  • \$\begingroup\$ "Each time an allocation is performed, a global heap allocator lock is obtained" This is most likely not true unless you are on an old operating system. Modern memory allocators have per-thread pools they can allocate from, and a thread might not even need to use a global lock to allocate more if its pool has run out. That said, even if it doesn't serialize, it's still quite bad to perform allocations while holding a lock. \$\endgroup\$
    – G. Sliepen
    Sep 13 '21 at 13:28
  • \$\begingroup\$ @G.Sliepen "This is most likely not true unless you are on an old operating system" - this is true, but it really depends on the language runtime more than the operating system. In most cases, the runtime does its own small block allocation and only gets larger blocks from the OS. The OS has a hierarchy of page table locks for that purpose, usually, so the contention for "large" blocks is indeed as small as can be. On some OSes, there's a decently performing heap allocator API (like on Windows), but that's also a mostly userspace mechanism and could be thought of as a "runtime" library. \$\endgroup\$ Sep 13 '21 at 13:53
2
\$\begingroup\$

Kuba makes excellent points in his answer. I'm going to present some alternatives though:

Keep it simple

A lot of complexity in your code (and also in Kuba's answer) comes from opening and closing the log file repeatedly. Things simplify greatly if you open it once and keep it open until the Logger is destroyed. Then the code becomes:

class Logger {
public:
    Logger(const std::string &filename): file(filename) {}
    void log( const char* text, LoggerType type);
    void log(/* other variants */);
private:
    std::mutex mutex;
    std::ofstream file;
};

void log(const char* text, LoggerType type)
{
    std::ostringstream stream;

    // Do all the formatting here without a lock
    ...

    // Write everything to the file in one go
    std::lock_guard lock(mutex);
    file.write(stream.rdbuf());
}

The operating system should already buffer writes to files so it's not waiting for the message to actually have been fully written to disk; it should return quite quickly. I therefore think that, unless your program is using this class to log a huge amount of data per second, this simple approach is just as efficient as Kuba's solution.

Don't use locks at all if possible

You might not need to serialize writing to the log file at all. Either your standard library already makes writes to a file thread-safe, or the operating system provides some lower-level I/O functions that are thread-safe. (In particular, Linux's libstdc++ has thread safe writes to std::ofstreams, and C's fwrite() is thread-safe even on Windows.) The only requirement is that a whole log message must be written to the file in a single I/O operation, otherwise messages can still be garbled as two threads interleave writing parts of the log message to the same stream.

\$\endgroup\$
3
  • \$\begingroup\$ it should return quite quickly It will syscall in a percentage of cases under the lock, and that's a rather bad idea. Well performing logging code is hardly trivial because the trivial ones can be easily made to perform extremely badly, precisely when it has the worst impact on application performance - under high load. Never mind that file.write adds another layer of unnecessary locking - you may as well use fwrite and get rid of the explicit lock in your implementation :) And the code I present is nothing compared to any fleshed out app-side logging solution anyway :) \$\endgroup\$ Sep 14 '21 at 17:29
  • \$\begingroup\$ I'd rather say that keeping it simple absolutely requires the use of a logging library, since - presumably - decent logging libraries are implemented with performance in mind and will do it right. \$\endgroup\$ Sep 14 '21 at 17:31
  • \$\begingroup\$ @Kubahasn'tforgottenMonica There are a lot of logging libraries out there, it's hard to tell which are decent. Which ones would you recommend? \$\endgroup\$
    – G. Sliepen
    Sep 14 '21 at 19:43

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.