Software Development

Use STL streams for easy C++ thread-safe logging

Streams in C++ are not thread-safe by default. However, using the power of STL and the coding techniques outlined here, you can benefit from the simplicity of streams while maintaining thread-safe code.

Streams offer a powerful abstraction for dealing with data, as they allow you to call generic read/write functions without caring where the data comes from or goes. With streams, you can use the same code for reading from console, file, sockets, etc.

C++ combines this power with operator overloading and provides us with the operators >> and << for reading from or writing to streams, as shown in Listing A.

Writing to streams is usually not thread-safe. As a matter of fact, even primitive functions like fread and fwrite are not required to be thread-safe. Properly implemented Standard Template Library (STL) streams, however, allow you to benefit from the simplicity of streams as well as keep your code thread-safe. Moreover, your existing code techniques using the operator << will remain viable, while thread-safety happens behind the scenes.

Why STL streams are not thread-safe by default
The C++ Standard does not specify whether writing to streams is thread-safe, but usually it's not. This is mainly due to efficiency issues. If writing to streams were thread-safe, it would require that all public (and some protected) functions also be thread-safe. According to the STL documentation, the class basic_ostream<>, which is the base class for all output streams, has plenty of public functions. Take the following code:
for (int idx = 0; idx < 1000000; ++idx) std::cout << idx << ' ';

If writing to std::cout were thread-safe, this would require at least 2,000,000 locks, which would pose a staggering performance bottleneck.

Moreover, if streams use stream buffers, the buffers would need to be made thread-safe as well. Extending an STL stream class would present an even larger thread-safe performance issue. Finally, even if STL streams were thread-safe, code such as that shown in Listing B would not be guaranteed to produce what you expect.

At first glance, it appears that Listing B should print the following on the console:
message from thread 1
message from thread 2


However, it will actually produce this:
message from message from thread 2
thread 1


That's because after the first thread succeeds in printing message and from, the second thread takes over, prints its entire message, and then the first thread continues printing from where it left off. This is only the simplest example of what can happen when your code is not made thread-safe.

Logging is easier than writing
Streams can allow for positioning, which is similar to having file access. You can go to the middle of a stream (if the stream allows you to) and start writing from there. However, when you log information, you always append it. You don't need any positioning—you're always at the end. To make things easier, our log classes will not even allow positioning.

Flushing and std::endl
As you know, you write to a stream using the operator <<, like this:
std::cout << val1 << val2 << …etc.

Internally, everything you write is kept in a stream buffer, and it's written to the underlying destination when either the programmer calls the flush() member function or the buffer gets full and is automatically flushed.

You tell a stream to flush in a simple manner: Write std::endl to it. This is equivalent to writing \n to the stream and then flushing it.

To make things easy and straightforward, let's use the convention that when a stream is flushed, the current message ends and a new message starts, as suggested by the code below:
// write 100 messages
for ( int idx = 0; idx < 100; ++idx)
    get_log() << "message " << idx << " - just for testing" << std::endl;


To make writing messages a thread-safe process, follow these five steps:
  1. Create an underlying stream U, to which you want thread-safe access.
  2. Create a stream S with a reference to U.
  3. Make sure each thread has its own stream S.
  4. When writing to the stream S, keep the data internally in a buffer until it's flushed.
  5. When stream S is flushed (the current message ends and a new message starts), it should write its buffer to the underlying stream U in a thread-safe manner, and then stream S should flush its buffer.

The code below demonstrates these steps:
thread_safe_log log = safe_cout(); // return thread-safe version of std::cout
for (int idx = 0; idx < 1000000; ++idx) log << idx << ' ';
log << std::endl;


Monitoring for flushing is not as easy as it looks. You have to override the stream buffer's sync() function. Listing C shows the basic_message_handler_log class, which hides all these details. Just remember that you can create your own log class and override the on_new_message function, which is called when a new message has been written to it.

The temporary variable trick
Let's recap: Each thread should have its own stream S, and S holds a reference to U (which needs thread-safe access). The easiest way for each thread to have its own stream S is to always deal with temporary variables. Temporary variables are inherently thread-safe, since only the thread that created the variable accesses it. The trick is to have a function get_log, which internally has a static variable (the underlying stream U) and returns a temporary variable (the stream S), as shown in Listing D.

In addition to being easier than most alternative methods, the technique shown in Listing D is most efficient. Locking happens only when the stream is flushed.

Solution 1
Class thread_safe_log derives from basic_message_handler_log shown in Listing C and overrides on_new_message, writing to the underlying log in a thread-safe manner. The question now is where should the critical section object be kept? To decouple thread_safe_log, create another class, internal_thread_safe_log, which deals with threading issues.

A get_log function will look like this:
thread_safe_log get_log()
{
    static underlying_stream_type U( args);
    static internal_thread_safe_log log( U);
    return log;
}


Remember the internal_thread_safe_log and thread_safe_log classes; i'll refer to them a lot throughout this article.

Listing E demonstrates the above techniques. Note that the code in Listing E needs the file CriticalSection.h, provided in Listing F, to operate properly.

You'll notice the following:
  • Both internal_thread_safe_log and thread_safe_log are typedefs of their basic_* counterparts. This follows existing practice, as std::ostream is a typedef of std::basic_ostream<char>, and std::streambuf is a typedef of std::basic_streambuf<char>, etc.
  • Each access to get_log() is followed by .ts(). This is necessary because some stream operations require the stream to be an lvalue. Simply put, an lvalue is something that can be put on the left side of operator=. A temporary variable is an rvalue and has to be turned into an lvalue.
  • The temporary variable stream S at its construction gets its state from stream U via copy_state_to, and at its destruction stream S copies that state back to U. You can think of the state of a stream as the information that dictates how certain data, such as the fill character, locale and other formatting information, will be written.

Overlooking these points could have serious consequences. Consider that U has been set to a German locale (therefore 5.235 is written as 5,235). If S used the default locale when printing numbers, the output would be interpreted totally wrong.

Listing E also contains a test. (To run it, you need Listings C and F.) The test uses out.txt as the underlying stream U. It creates 200 concurrent threads, each thread writing 500 messages, like this:
  • "writing double 5.23" (first type of message)
  • "message <idx> from thread <thread>" (second type of message)

When thread with index 10 writes the 11th message, U's locale is changed to German. All following messages will be "writing double 5,23" instead of "writing double 5.23".

Solution 2
The problem with the Listing E solution is that if 100 threads try to write at once, only one succeeds at a given time, while the others wait to acquire the lock. Depending on the underlying stream, executing m_underlyingLog << str; might take a long time, putting all the other threads on hold. This can soon become a traffic jam.

In function internal_thread_safe_log::write_message, the messages are appended into a queue. A dedicated thread keeps reading from this queue and writes the messages to the underlying stream. Function internal_thread_safe_log::write_message now contains only an addition of a pointer into a queue, which takes virtually no time, avoiding bottlenecks. Listing G shows the updated solution.

Here's what has changed between the two versions:
  • internal_thread_safe_log has a writer object.
  • Each writer object, thread_safe_log_writer, has its own dedicated thread that takes care of writing the messages to the underlying stream U.
  • Each writer object needs to create its own thread using a threading manager.

The role of the threading manager is to decouple platform-dependent threading issues (such as creating a new thread). We'll examine the threading manager later, but for now, the current threading manager is win32_thread_manager. The final solution will allow for other threading managers as well.

Solution 3
Depending on the number of logs and/or the number of threads your applications should use, Solution 2 might not be appropriate. Multiple logs could share a single thread that will write to each of those logs. Solution 3 provides this functionality through these key features:
  • A writer thread
  • Multiple logs, which register themselves to the writer thread
  • Each log, within the writer thread, has a given priority. (The log's constructor includes the log's priority as an extra parameter.) Based on this priority, the writer thread will prefer writing to certain logs over others.

For example, imagine three logs: log1 has priority 6, log2 has priority 3, and log3 has priority 1. (Their priorities add up to 10 = 6 + 3 + 1.) In the writer thread, for every 10 writes, six will be to log1, three will be to log2 and one will be to log3. If trying to do a write for a log when there is no message in the log's queue, this write is ignored.

The test has been modified in Listing H to include the following features:
  • The new test includes 10 logs: out0.txt, out1.txt, …out9.txt.
  • The log at <idx> has a priority of 10 * (idx + 1)^2. Note that log out3.txt has a of priority 10 * 4 * 4 = 160.
  • 20 threads write to out4.txt.

When you run Listing H, note that the logs with greater numbers fill somewhat faster than the rest due to their priority.

Solution 4
Solution 4 allows you to choose between Solution 2 and Solution 3, depending on your application needs. Switching from one solution to another will mean changing one or two lines of code within your get_log() functions. Such a multiformat solution requires these features:
  • Two internal_thread_safe_log classes: internal_thread_safe_log_ownthread, which matches to a single, dedicated log; and internal_thread_safe_log_sharethread, which is shared by multiple logs.
  • The internal_thread_safe_log_sharethread requires a corresponding thread_safe_log_writer_sharethread, the thread that the logs need to share.

Listing I shows how simple it is to change from internal_thread_safe_log_ownthread to internal_thread_safe_log_sharethread, and vice versa. Listing J shows the complete implementation of Solution 4.

Listing J includes these added features:
  • The internal_thread_safe_log classes now accept an extra template parameter, the thread_manager, which is used to decouple platform-dependent threading issues, as explained below.
  • Listing J does not need CriticalSection.h necessary for Listing F; since CriticalSection.h is encapsulated in thread_manager.
  • Each time you flush the stream, a new message starts, meaning that the last message will never be flushed. Thus, the last message needs special processing. The message_handler_log.h has been changed, as highlighted in >Listing K, to allow the processing of the last message.

Forgetting to flush is probably a mistake, as >Listing L shows. We therefore make flushing prior to each temporary variable's destruction a constraint, as shown in >Listing M. Implementing this constraint is quite simple: See thread_safe_log::on_last_message.

In the destructor of thread_safe_log, we protect ourselves from dealing with invalid references. Dealing with temporaries brings us a special set of problems: Using a temporary after it's been destructed ([temp-destructed]).

The test has also changed a bit:
  • We have the 10 logs (logs 0-9) from the last test (sharing a thread).
  • We also have 10 logs (logs 10-19), each with its own thread.
  • 10 threads write to a given log (threads 4, 24, 44, … 184 write to the fourth log).

Finally, let's discuss the threading managers. A threading manager is a class that dictates how some needed threading issues should be dealt with. It has to provide the following:
  • thread_obj_base: This class should be passed as argument when creating a thread; its overloaded operator() is executed on the other thread.
  • sleep( nMillisecs): The current thread will sleep for nMillisecs milliseconds.
  • create_thread( thread_obj_base & obj): This creates a thread and executes obj.operator() on it.
  • critical_section and auto_lock_unlock classes: These behave like CCriticalSection and CAutoLockUnlock, as shown in Listing F.

I provided two threading managers:
  • win32_thread_manager: This is the threading manager for Win32 applications.
  • boost_thread_manager: This is the threading manager if you're using boost threads ([boost]).

In your code, #define USE_WIN32_THREAD_MANAGER to use the first as default and USE_BOOST_THREAD_MANAGER to use the last as default. Or you can provide your own and #define DEFAULT_THREAD_MANAGER as your_threading_manager_class.

Run Listing J, (Remember, it needs the latest message_handler_log.g—Listing K.) You may have noticed that Listing J contains quite a few classes. This is why I've split them into multiple files.

Grasping the complexity
Using thread_safe_log and internal_thread_safe_log_* classes allows you to log in the way you're most used to and to gain the benefits of thread-safety while still being efficient. Existing code and utility functions and classes that use STL streams can now be used in a thread-safe manner. Refactoring existing applications is also easy. Thread-safety is a difficult subject to grasp, but with a little effort you can master it and enjoy its advantages.
0 comments