How to add thread-safety in a logging library?

[ZHENG Zhong]

Hi,

I implemented a small logging library with the API like this:

[snip]
logger& log = log_manager::instance().get_logger("my_logger");
log.stream(DEBUG) << "this is a debug message" << std::endl;
log.stream(INFO) << "this is an info message" << std::endl;
[/snip]

Every logger has a unique name, and manages an output stream
(std:stream). The 'stream(log_level_t)' member function returns an
ostream_proxy object, which is implemented as the following:

[snip]
class ostream_proxy {

public:

// other member functions...

template<typename T>
ostream_proxy& operator<<(T const& t) {
(*os_) << t;
return *this;
}

private:
std:stream* os_; // ostream_proxy objects from the same logger
object share
// the same output stream.
};
[/snip]

Thus it is possible that two threads retrieve the same logger object
and write messages to the logging stream at the same time.

Now i want to add thread-safety to my logging library, and i realize
that in ostream_proxy, the statement "(*os_) << t;" is not thread-safe
(std:stream is not thread-safe, right?). So i need to re-implement
the operator << in ostream_proxy like this:

[snip]
class ostream_proxy {

public:

// other member functions...

template<typename T>
ostream_proxy& operator<<(T const& t) {
{
boost::mutex::scoped_lock lock(*os_mutex_);
(*os_) << t;
}
return *this;
}

private:
std:stream* os_; // ostream_proxy objects from the same
logger object
boost::mutex* os_mutex_; // share the same output stream and the
same mutex.
};
[/snip]

In this way, i can guarantee that at any moment, there is at most one
thread that calls "(*os_) << t;".

But since logging may be an action that is frequently performed, the
code above may be too expensive to bear... Surely i can use a policy
to allow user to choose if s/he want thread-safety or not. But in a
multi-threaded application, user still has to pay for logging...

So i would like to know if such implementation is proper, or if there
is a way to make that better.

I would appreciate your advice. Thanks!

 

[=?ISO-8859-1?Q?Erik_Wikstr=F6m?=]

Hi,

I implemented a small logging library with the API like this:

[snip]
logger& log = log_manager::instance().get_logger("my_logger");
log.stream(DEBUG) << "this is a debug message" << std::endl;
log.stream(INFO) << "this is an info message" << std::endl;
[/snip]

Every logger has a unique name, and manages an output stream
(std:stream). The 'stream(log_level_t)' member function returns an
ostream_proxy object, which is implemented as the following:

[snip]
class ostream_proxy {

public:

// other member functions...

template<typename T>
ostream_proxy& operator<<(T const& t) {
(*os_) << t;
return *this;
}

private:
std:stream* os_; // ostream_proxy objects from the same logger
object share
// the same output stream.
};
[/snip]

Thus it is possible that two threads retrieve the same logger object
and write messages to the logging stream at the same time.

Now i want to add thread-safety to my logging library, and i realize
that in ostream_proxy, the statement "(*os_) << t;" is not thread-safe
(std:stream is not thread-safe, right?). So i need to re-implement
the operator << in ostream_proxy like this:

[snip]
class ostream_proxy {

public:

// other member functions...

template<typename T>
ostream_proxy& operator<<(T const& t) {
{
boost::mutex::scoped_lock lock(*os_mutex_);
(*os_) << t;
}
return *this;
}

private:
std:stream* os_; // ostream_proxy objects from the same
logger object
boost::mutex* os_mutex_; // share the same output stream and the
same mutex.
};
[/snip]

In this way, i can guarantee that at any moment, there is at most one
thread that calls "(*os_) << t;".

I have not given this issue a lot of though but with the code above you
protect each << operation with a lock, however if you have two threads
running and both have a statement like this:

log.stream(DEBUG) << "Foo: " << foo << ", Bar: " << bar << std::endl;

(i.e. multiple << on one line) you only lock each << and there can be
interleaving from multiple threads giving you a result like this in the log:

Foo: Foo: 4 Bar: 32 Bar: 5

But since logging may be an action that is frequently performed, the
code above may be too expensive to bear... Surely i can use a policy
to allow user to choose if s/he want thread-safety or not. But in a
multi-threaded application, user still has to pay for logging...

So i would like to know if such implementation is proper, or if there
is a way to make that better.

I would appreciate your advice. Thanks!

Locks are usually more expensive if they are heavily contended, so if
you have many threads that perform logging (or a few threads which logs
a lot) then you might want to consider giving each thread its own,
thread local, log.

 

[James Kanze]

I implemented a small logging library with the API like this:
[snip]
logger& log = log_manager::instance().get_logger("my_logger");
log.stream(DEBUG) << "this is a debug message" << std::endl;
log.stream(INFO) << "this is an info message" << std::endl;
[/snip]
Every logger has a unique name, and manages an output stream
(std:stream). The 'stream(log_level_t)' member function returns an
ostream_proxy object, which is implemented as the following:
[snip]
class ostream_proxy {
public:
// other member functions...
template<typename T>
ostream_proxy& operator<<(T const& t) {
(*os_) << t;
return *this;
}
private:
std:stream* os_; // ostream_proxy objects from the same
// logger object share
// the same output stream.
};
[/snip]
Thus it is possible that two threads retrieve the same logger object
and write messages to the logging stream at the same time.
Now i want to add thread-safety to my logging library, and i realize
that in ostream_proxy, the statement "(*os_) << t;" is not thread-safe
(std:stream is not thread-safe, right?).

This depends on your implementation. All of those I know are,
in the sense that they define and document what happens in a
multithreaded environment. Generally, the better ones specify
that you can't access the same ostream object (or streambuf
object) from two different threads without extern
synchronization, but that you can access two different ostream
(or streambuf) objects. (Note that two different ostreams can,
in certain cases, share the same streambuf object.)

Which is no big deal, because as Erik points out, operator<<
doesn't have the correct granularity.

So i need to re-implement
the operator << in ostream_proxy like this:
[snip]
class ostream_proxy {
public:
// other member functions...
template<typename T>
ostream_proxy& operator<<(T const& t) {
{
boost::mutex::scoped_lock lock(*os_mutex_);
(*os_) << t;
}
return *this;
}
private:
std:stream* os_; // ostream_proxy objects from the same
logger object
boost::mutex* os_mutex_; // share the same output stream and the
same mutex.
};
[/snip]
In this way, i can guarantee that at any moment, there is at most one
thread that calls "(*os_) << t;".

I have not given this issue a lot of though but with the code above you
protect each << operation with a lock, however if you have two threads
running and both have a statement like this:

log.stream(DEBUG) << "Foo: " << foo << ", Bar: " << bar <<
std::endl;

(i.e. multiple << on one line) you only lock each << and there
can be interleaving from multiple threads giving you a result
like this in the log:

Foo: Foo: 4 Bar: 32 Bar: 5

Exactly. The usual solution is to create the proxy each time,
and have it manage the lock. Note, however, that the proxy will
typically be a return value of the log.stream() function; as
such it may (or may not) be copied one or more times. The
solution here is to use what I call the idempotent copy pattern;
basically, the class maintains a count of its copies, the C++
destructor only decrements this count, and what logically serves
as a destructor is only called when the last copy is destroyed.

The simplest way to do this is to use a variant of the
compilation firewall, where the proxy class itself only holds a
pointer to the actual data. If the pointer is a
boost::shared_ptr, instead of a raw pointer, or a scoped_ptr,
you get the idempotent copy semantics automatically. In his
case, all the implementation class would have to contain was the
shared lock. The constructor for the proxy might look something
like:

log_proxy::log_proxy(
std:stream* dest )
: myDest( dest )
{
if ( myDest != NULL ) {
myLock = new boost::scoped_lock( mutexForThisStream )
}
}

Locks are usually more expensive if they are heavily contended, so if
you have many threads that perform logging (or a few threads which logs
a lot) then you might want to consider giving each thread its own,
thread local, log.

Locks, even heavily contended locks, are usually very
inexpensive compared to actual IO. If logging is inactive, dest
is NULL, and you don't lock. If logging is active, you're doing
IO, so it doesn't matter (and you need the lock, whatever).

 

[Roland Pibinger]

I implemented a small logging library with the API like this:
[snip]
logger& log = log_manager::instance().get_logger("my_logger");
log.stream(DEBUG) << "this is a debug message" << std::endl;
log.stream(INFO) << "this is an info message" << std::endl;
[/snip] [...]
Thus it is possible that two threads retrieve the same logger object
and write messages to the logging stream at the same time.

This is because you use the Singleton Anti-pattern for your logger. If
you created a logger object for each thread and passed it to the
functions (or passed a context object that provides access to the
logger) you would not run into the problems you describe.

Now i want to add thread-safety to my logging library, and i realize
that in ostream_proxy, the statement "(*os_) << t;" is not thread-safe
(std:stream is not thread-safe, right?). So i need to re-implement
the operator << in ostream_proxy like this: [...]
But since logging may be an action that is frequently performed, the
code above may be too expensive to bear.

If you insist on using global objects try TLS
(http://en.wikipedia.org/wiki/Thread-local_storage) and let each
thread write to a different logging handler.