How to add thread-safety in a logging library?

Discussion in 'C++' started by ZHENG Zhong, Aug 3, 2007.

  1. ZHENG Zhong

    ZHENG Zhong Guest

    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::eek: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::eek: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::eek: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::eek: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!
    ZHENG Zhong, Aug 3, 2007
    #1
    1. Advertising

  2. 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::eek: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::eek: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::eek: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::eek: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
    =?ISO-8859-1?Q?Erik_Wikstr=F6m?=, Aug 3, 2007
    #2
    1. Advertising

  3. ZHENG Zhong

    James Kanze Guest

    On Aug 3, 1:26 pm, Erik Wikström <> 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::eek: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::eek: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::eek: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::eek: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::eek: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
    James Kanze, Aug 4, 2007
    #3
  4. 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::eek: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
    Roland Pibinger, Aug 4, 2007
    #4
    1. Advertising

Want to reply to this thread or ask your own question?

It takes just 2 minutes to sign up (and it's free!). Just click the sign up button to choose a username and then you can ask your own questions on the forum.
Similar Threads
  1. Hans

    What is thread safety?

    Hans, Oct 11, 2004, in forum: ASP .Net
    Replies:
    1
    Views:
    582
    Sahil Malik
    Oct 12, 2004
  2. George Ter-Saakov

    LiteralControl thread safety.

    George Ter-Saakov, Apr 5, 2004, in forum: ASP .Net
    Replies:
    1
    Views:
    326
    Martin Dechev
    Apr 6, 2004
  3. Simon Harvey

    A thread safety question

    Simon Harvey, Aug 6, 2004, in forum: ASP .Net
    Replies:
    3
    Views:
    401
    Alvin Bruney [MVP]
    Aug 6, 2004
  4. thechaosengine

    Thread safety when subclassing the Page class

    thechaosengine, Dec 10, 2004, in forum: ASP .Net
    Replies:
    2
    Views:
    394
    Scott Allen
    Dec 10, 2004
  5. =?Utf-8?B?RGlmZmlkZW50?=

    Thread-safety and Singleton methods

    =?Utf-8?B?RGlmZmlkZW50?=, Jan 13, 2005, in forum: ASP .Net
    Replies:
    1
    Views:
    508
    Karl Seguin
    Jan 13, 2005
Loading...

Share This Page