qpid-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Alan Conway <acon...@redhat.com>
Subject Re: Random witterings about logging
Date Sun, 06 May 2007 01:53:10 GMT
On Fri, 2007-05-04 at 15:10 +0100, Andrew Stitcher wrote:
> It occurs to me that if you have a logging structure like 
> 
> inline void log(A a, B b, C c)
> {
>     if (log_level & log_mask)
> 	real_log(a, b, c);
> }
> 
> Then (assuming you do get a correct inlining), you won't have any
> overhead except the test in the not taken case (none of the parameter
> conversions, pushes happen at all).

That depends on what the formal and actual types A,B,C are. For example
this is a disaster: 

inline void log(const string& x);
// In code
log("foo"); // heap allocate and copy on every call log or no log!

Similar problem with log(boost::format("Foo=%s" % foo)) or 
ostringstream msg; msg << "Foo=" << foo << endl; log(msg);

> This should be exactly as good as a macro (in theory).

It just ignores the hard part of the problem: a fast, flexible and type
safe way of formatting messages that isn't so irritating as to
discourage developers from logging. At this point I think we have 3
options:

1. rlog does it with printf style varargs which is fast, flexible but
not type safe.

2. pantheios has a clever templated "string shim" type which records the
parameter value but doesn't format as a string until/unless you actually
get to recording a log. It's fast, flexible and type safe but drags in a
whole new extensions-to-STL library.

The macro I had in mind was something like:
#define QPID_LOG(EXPR) do { \
 if (needLog) { ostringstream msg; msg << EXPR; doLog(msg.str()); }

Which allows all of the following:
QPID_LOG("hello");
QPID_LOG("foo=" << foo);
QPID_LOG(boost::format("foo=%d" %foo))

So you have support for plain char[], stream style AND printf style 
formatting without the type safety issues of varargs.

> I'm not actually sure that the registration approach of rlog is in fact
> better than the more normal approach:
> 
> rlog approach:
> 
> if (fp)
>     fp(a, b, c);
> 
> usual approach
> 
> if (log_level & log_mask)
>     real_log(a, b, c);
> 
> These are pretty much as fast as each other, actually the function
> pointer indirection might be slower in the (less important) taken case.

You're missing the intersting bit: rlog does not log against a simple
mask. You can selectively enable logging in "subsystems" tagged by a
macro value and in individually named source files. The clever bit is
that instead of doing some kind of lookup at each log statement to see
if the current file/subsystem are enabled, you only check a function
pointer. The hard work of updating all the function pointers only
happens once the first time you enter a log statement and again if/when
you change the logging paramters at runtime.

> The important thing is to avoid a function call in the test (which is
> what pantheois uses incidentally, so even that can't be so slow)

Not sure what pantheios offers in terms of selecting subsets of code to
log. log4c** like log4j has to do a tree walk as well as a bitmask check
to determine if logging is enabled for a particular statement.

> The more usual approach is easier to correctly thread as you can fairly
> easily atomically update a global log_mask - the real issue is sync
> across processors. The rlog approach is harder as you have to use some
> sort of map structure to find your "fp", and as you might have to add to
> the map, it has to have some locking.

The usual approach is only easy if you offer *nothing but* bitmask
check. I'm strongly in favour of having more control, high volume
logging for debugging is pretty much useless unless you can say "but
only for the foobar module". Otherwise you're flooded in so much useless
junk that you cant find or worse can't even reproduce the thing you're
interested in (I've seen production software that explodes on takeoff if
you turn on all the logging :)

There are actually 3 aspects to consider:

1. Avoiding expensive format operations if you're not going to log.
2. Making fast logging decisions while allowing selective enabling of
logging
3. (not covered above) Doing fast formatting when you *do* log.

Pantheios is good at 1 & 3 no idea what flexibility it has for 2. It's
packaged like a pig, drags in yet another STL++ library and has limited
backends.

rlog is good at 1,2 and 3 but doesn't look thread safe. Also has limited
backends.

My macro is good at 1, still need cleverness for 2 (Maybe a threadsafe
version of the rlog trick) is as good as ostream/boost::format for 3 and
we're on our own for backends.

log4c*** provides rich backends and selective logging with sort-of-fast
logging decisions. It also has a huge range of backends. Pantheios
recommends using their frontend & log4cxx backends, but I don't fancy
double dependency.

The pantheios tests suggest that while they are faster at formatting
it's not as huge a deal, the dramatic graphs are the ones about format
avoidance. 

I think the ideal solution is macro+ostream+rlog-like test, with  an
atomic pointer get+compare 0 as the only overhead for unlogged.  I'm not
convinced the time & effort to write it ourselves is well spent but I'm
equally not convinced we should adopt any of the options so far. Still
confused

Alan.


Mime
View raw message