Re: [boost] Re: Re: Re: Logging Library -- Formal Review Request

From: Caleb Epstein (caleb.epstein_at_[hidden])
Date: 2005-05-02 12:28:29

On 4/30/05, Gennadiy Rozental <gennadiy.rozental_at_[hidden]> wrote:
> Sorry. I am not that deep ;)) First of all I am not familiar with detail of
> this submission and second I just talking from user prospective. And from
> that prospective what proposed implementation yields may not be ucceptable
> cause it break order of events.
> 
> I wonder what it's going to pring in more complicated cases:
> 
> BOOST_LOG(..)  << "Print result of f(): " << f() << " and g()" << g();
> 
> void f() {
> BOOST_LOG(..)  << "Enter f()";
> 
> BOOST_LOG(..)  << "f() inside uses m(): " << m();
> 
> BOOST_LOG(..)  << "Exit f()";
> }
> 
> void g() {
> BOOST_LOG(..)  << "Enter g()";
> 
> BOOST_LOG(..)  << "g() inside uses m(): " << m();
> 
> BOOST_LOG(..)  << "Exit g()";
> }
> 
> Gennadiy
> 
> P.S. Could you explain a bit more how cashing and threading are involved
> here

Within any block (or a block nested within that block), writes to will
appear in the proper order.  If my reading of the code is correct, the
way the BOOST_LOG macro works when a log is enabled is to
(oversimplifying) return a proxy stream object ("logger_keeper" which
inherits from "enabled_logger") which will be the target of the
operator<< calls.  When this proxy object is destroyed, the entire
message gets written.

So something like this:

BOOST_LOG (x) << "Result of f: " << f ().

Turns into something more like (expanding out the code inside the
classes and greatly oversimplifying, but this iis the gist):

if (!x.is_enabled ())
    ;
else
    {
    ostringstream s;
    s << "Result of f: " << f ();
    write_msg (logger::manager (), x, s.str ());
    }

So if there are nested logging calls inside of "f" that are destined
for the logger "x", they will hit the output device *before* the
caller's message does.

You suggested something like this:

> a.cpp:14: Print result of f():
> b.cpp:75: Enter f()
> b.cpp:95: Exit f()
> a.cpp:14:  1234

If I understand the behavior you desire, the string "Print result of
f(): " would be logged either (1) immediately or (2) as soon as there
were any logging calls from a different scope (e.g. the "Enter f()").

The first option to me suggests no buffering between the loggers ("x"
in this case) and the output devices (the things that write to files
etc).  This would likely offer poor performance, and would lead to
intermixing of output from multiple threads just like plain iostreams.
 In other words, if multiple threads are writing to the same logger
simultaneously, their messages would potentially be fragmented and
mixed wherever they are separated by an <<.  Perhaps a thread-specific
stream could be used to prevent this.

The second option is an interesting one, but is similar or identical
to the first case I believe.  The target of the operator<< calls could
keep a stack of the logging "scope" and pop that stack whenever a
scope is exited (e.g. a BOOST_LOG call is complete).  Whenever the
scope changed, the desired prefix (e.g. filename, line number,
timestamp, thread ID, etc) would be emitted.  This would need to be
kept in thread-specific storage for the same reaons mentioned above.

Am I totally off base here in terms of what you're suggesting and how
it might be implemented?

-- 
Caleb Epstein
caleb dot epstein at gmail dot com