Velocity Reviews - Computer Hardware Reviews

Velocity Reviews > Newsgroups > Programming > C++ > How to add thread-safety in a logging library?

Reply
Thread Tools

How to add thread-safety in a logging library?

 
 
ZHENG Zhong
Guest
Posts: n/a
 
      08-03-2007
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!

 
Reply With Quote
 
 
 
 
=?ISO-8859-1?Q?Erik_Wikstr=F6m?=
Guest
Posts: n/a
 
      08-03-2007
On 2007-08-03 12:27, ZHENG Zhong wrote:
> 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.

--
Erik Wikström
 
Reply With Quote
 
 
 
 
James Kanze
Guest
Posts: n/a
 
      08-04-2007
On Aug 3, 1:26 pm, Erik Wikström <(E-Mail Removed)> wrote:
> On 2007-08-03 12:27, ZHENG Zhong wrote:
> > 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 )
}
}

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


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

--
James Kanze (GABI Software) email:james.kanze:gmail.com
Conseils en informatique orientée objet/
Beratung in objektorientierter Datenverarbeitung
9 place Sémard, 78210 St.-Cyr-l'École, France, +33 (0)1 30 23 00 34


 
Reply With Quote
 
Roland Pibinger
Guest
Posts: n/a
 
      08-04-2007
On Fri, 03 Aug 2007 10:27:02 -0000, ZHENG Zhong wrote:
>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.


--
Roland Pibinger
"The best software is simple, elegant, and full of drama" - Grady Booch
 
Reply With Quote
 
 
 
Reply

Thread Tools

Posting Rules
You may not post new threads
You may not post replies
You may not post attachments
You may not edit your posts

BB code is On
Smilies are On
[IMG] code is On
HTML code is Off
Trackbacks are On
Pingbacks are On
Refbacks are Off


Similar Threads
Thread Thread Starter Forum Replies Last Post
Re: How include a large array? Edward A. Falk C Programming 1 04-04-2013 08:07 PM
Logging to a file and closing it again properly (logging module) Christoph Haas Python 0 06-12-2006 09:58 PM
logging buffered vs. logging history Christian Roos Cisco 4 02-05-2006 10:55 PM
java.util.logging, where to put logging.properties? janne Java 0 09-10-2004 10:18 AM
[java.util.logging] logging only to _one_ file Stefan Siegl Java 0 08-27-2003 12:29 PM



Advertisments