Re: [boost] [log] Boost.Log Review...

Subject: Re: [boost] [log] Boost.Log Review...
From: Andrey Semashev (andrey.semashev_at_[hidden])
Date: 2010-03-13 07:43:30

On 03/12/2010 03:32 AM, Sean Chittenden wrote:
>
> After using this library for several months now, I have distilled a
> quick summary for those coming up to speed on how to use Boost.Log
> and its components.  This is specific to how I'm using Boost.Log, but
> I think this is the desired use-case for most users of Boost.Log (esp
> since this is the common path for users of ASIO).
>
> - Your application is littered with Log Statements that are tagged
> with different Severity Levels - Log Statements consist of a Logger
> (a collection of Sinks), a Precondition (e.g. a severity) and Log
> Record instance data (most commonly a message) - Loggers are
> collections of Sinks (e.g. a file and the console) - Loggers
> conditionally accept Log Records if one of a Logger's Sinks returns
> true for a Precondition (e.g. only create a Log Record if the log
> statement's Severity Level greater than or equal to the Severity
> Level configured in the Sink) - Instructions required to create a Log
> Record won't be executed if a Sink doesn't accept a Log Record -
> Sinks can be configured to queue accepted Log Records (e.g. async
> frontends) before passing them to one or more Backends for printing
> (e.g. console text file, SNMP trap)
>
> The Boost.Log system can be configured to mutate individual Log
> Records through the manipulation of the following three types of
> information:
>
> - Channels represent a way of tying together a collection of related
> systems (e.g. security, network, application).  Think of channels as
> a Sink-level observer that stamps the channel on a Log Record. -
> Severities represent the importance of a message (a Log Statement
> precondition that a Sink-level Observer could stamp a Log Record) -
> Attributes represent per-Log Record information (a string key/value
> in a Log Record instance)
>
> Backends can then format the output based on the Attributes of a
> particular Log Record.
>
>
> The above wasn't explicitly distilled in the documentation in a
> single place, but I think future developers would find it very useful
> to see that spelled out explicitly.  Given the extremely modular
> design of the library, I understand why the docs are the way they are
> and know that some of this is touched on in the Design Overview, but
> until I became very competent with the library, the documentation
> seemed too abstract.  Despite the importance of logging, becoming a
> logging expert was tangential to the problem I was trying to solve
> and I would have personally found the above summary very useful.

Well, that summary may describe your use case very well, but it is by no 
means complete with regard to Boost.Log as a whole. I would even say 
it's misleading in some parts - in particular: "Loggers are collections 
of Sinks" and "Think of channels as a Sink-level observer".

> A hindsight 20/20 architecture and terminology for Boost.Log could be
> simplified in terms of:

What is "20/20"? I'll continue my answers assuming that the following 
was your understanding of the current Boost.Log architecture.

> *) Log Record pre-conditions.  Sinks control whether or not a Log
> Record is to be generated

Looks like you're confusing sinks with filters. Also, don't forget about 
the global filter.

> *) Loggers.  A container for zero or more Sinks

Loggers and sinks are not related, and that is the intention of the 
library. Different log records made through the same logger may end up 
in any sink(s). This gives the ability to encapsulate logging 
configuration in a single place of the application, without affecting 
every place where logging is used.

> *) Sinks.  A frontend that queues Log Records

Only async frontends use record queuing.

> *) Sink Compile-Time Attributes/Observers.  Observers that are configured at
> compile time, augment Log Records, and stamp Log Records as they pass
> through the Sink (e.g. severity, channels, etc)

There is no model of this in Boost.Log. I take it that you'd like it to 
be there. More on this below.

> *) Backends.  A formatter that orders and writes Log Records from Sinks

Roughly speaking, yes. But "writes" is not the accurate term, as no 
actual writing may take place.

> *) Log Records.  A container of information that is populated by the user's
> application, Sinks and Backends (possibly Loggers as well)

Nod.

> *) Log Record Compile-Time Attributes.  Compile-time members of a Log Record
> struct

Same as "Sink Compile-Time Attributes/Observers".

> *) Log Record Runtime Attributes.  Key/Value members of a Log
> Record stored in a std::map (currently how Attributes are
> implemented)

The current solution is much equivalent to std::map, but is not.

> I'd imagine most developer would want async messaging between Sinks
> and Backends.

That assumption is not valid. One of the most frequent application of 
logging is the debug output, which doesn't work well with async logging. 
In fact, I expect synchronous logging to be more common than in-process 
asynchronous one.

> Those that don't, could make use of a Sink
> Compile-Time Attribute that always sets the flush bit on a Log
> Record.

Flushing the other thread through the flag will be a time hog. Doing 
this on a per-record basis will bring performance down to an unusable level.

> The notion of a "global logging core" bothers me.  Having singletons
> of loggers and sinks in TSS is very good from a utility perspective.
> Admittedly I don't know how the global logging core is used beyond
> being a nob that can be turned to enable/disable logging, nor have I
> profiled it yet, but any centralized core bugs me in a highly
> threaded environment.

The core doesn't limit scalability as it doesn't block threads unless 
the user wants to configure it (e.g. add/remove sinks or global 
attributes). The tests I mentioned in another thread confirm that.

> Why does Boost.Log roll its own TLS/TSS support?
> boost/log/detail/thread_specific.hpp vs. boost/thread/tss.hpp  There
> may be a very good reason, I just didn't see it when I was looking
> through the library.

Because it's more efficient than what Boost.Thread provides. When 
thread_specific_ptr is fast enough, I'll be glad to switch back to it.

> Can Log Records be pool managed somehow?

No. If you're concerned with dynamic memory allocation, it's better to 
use libraries dedicated to that problem (Google perftools, for instance).

> I understand why std::map is used to store attributes (ease of
> use/flexibility), but at the same time, I do wish that frequently
> stored attributes could be baked in at compile time.
>
> This is my biggest gripe with the library, actually.  I would like my
> application to err on the side of making use of compile-time
> information at the expense of the time required for compiling the
> source.  Storing things in a std::map seems lazy and brutish, for the
> lack of a better description.  Flipping things on its head so that
> Log Records define Loggers, Sinks and Backends would be ideal, IMHO,
> and would solve most of my gripes.  This is a design decision, but
> the contents of Log Records is of more importance than the backends.
> Boost.Log appears to be designed from Backends to Log Records vs. Log
> Records to Backends, which is the way data flows through an
> application (this would be my preference).  For example:

[snip]

> Observers could then be placed on Sinks that would stamp Log Records
> with Severities, or Channels, or in whatever hodge-podge
> configuration the developer wanted and such examples would be very
> cookbook.

Now that you presented a code snippet, your suggestion makes more sense 
to me. Let me express my thoughts on it in two parts:

1. Custom log records. Yes, the model of "mandatory" attributes look 
promising. It could, at least, partially solve the problem of possible 
library misconfiguration that was highlighted in another review. I 
imagine that some kind of log record prototype (or factory) should be 
defined by the user in order to be able to construct log records with 
the specific set of attribute values. Filters and formatters could then 
request these mandatory attribute values without having to worry about 
their absence. Lookup performance may also be higher, but I doubt it 
will be compile-time. The idea is quite vague now but after some 
thinking over it might become a good addition to the library.

2. Designing sinks (and the core, I presume) after the log records. No, 
that looks unacceptable to me, at least for what Boost.Log tries to 
achieve. This would introduce too much coupling between the logging side 
of the library (which tends to be exposed to many parts of the 
application) and the consuming side (which tends to be configured in a 
single place of the application). To my mind, these sides of the library 
should be maximally decoupled. Also, it's not clear how to support 
multiple log record types in such a design.

> *) Log Records are highly reused and seem like ideal candidates for a
> TLS freelist.

I consider memory management out of scope of Boost.Log.

> *) Global loggers vs. per-object references to singletons

Not sure I understand.

> *) Channel severity loggers example

That example wouldn't be much different from the ones in sections about 
severity_logger or channel_logger. But I'll add a code sample.

> *) Setting up an initial console logger as
> line one in main()

Hmm. Ok, I'll add something about that to the tutorial.

> *) Changing a backend filter at a later date

Just call set_filter on the backend, that's all.

> *) Using async logging for INFO level logs, but switching to sync for
> CRIT errors.

You can register two sinks - one synchronous and one asynchronous, and 
set their filters accordingly.

> *) Obtaining the severity of a particular logger

You mean, the default severity? There's no public API for this, but 
there's a protected function default_severity in the logger feature. Why 
would you need it?

> *) How do you remove log events given a severity level at compile
> time.  Currently this isn't explicit defined in the documentation
> like it is in Google's glog library:
>
> http://google-glog.googlecode.com/svn/trunk/doc/glog.html#strip

The library has no direct means for that. Users can conditionally define 
their logging macros, based on BOOST_LOG_SEV or pure C++ interface and 
then enable or disable the particular logging statements from the source.

> *) Is there a way to set a bit in a Log Record that overrides a
> Sink's filter?  For instance, there are certain events that I want to
> make sure go to the console 100% of the time without changing the
> severity of the log message.  Do I just log twice?  It'd be keen if
> Log Records could have a bit that could be set and would override a
> filter.
>
> bool log_to_console = true; BOOST_LOG_SEV_CONS(lg, warning,
> log_to_console)<<  "my message";

You can set an attribute (say, "Emergency") for that record, and setup 
filters so that whenever this attribute is present, the record is passed 
on to the console backend.

> *) It should be noted that the internal async log message queuing
> mechanism uses a vector and during very bursty logging activity that
> the vector can grow large in size and doesn't ever reduce in size.
> This is a known limitation and the use of a vector was chosen to
> facilitate atomic append operations for log records.  Using a
> std::deque would be preferred for bursty applications that way space
> could be reclaimed easier, but as Andrey pointed out, it would
> require a full mutex which would reduce the performance of the
> library.

There is no vector in the async frontends. The problem with the current 
queuing mechanism is not the storage strategy but the lack of queue 
boundaries. But I agree, I should have drawn attention to this aspect in 
the docs. Will do.

> *) I find the argument against Lazy Streaming of attributes to be
> weak.
>
>  Current BOOST_LOG() expands to a for() loop where the contents of
> the for() loop aren't executed unless a Sink in a Logger accepts the
> record.
>
> So why can't Log Records have compile-time attributes that can be
> populated with typed attributes in a stream?
>
> And then be able to extract the compile-time attribute in a backend:

Just as it is said in the rationale - the streaming expression is _not_ 
executed until _after_ the filtering is done. And filtering already 
involves attribute values, so there's no way to use these attribute 
values you specified in the streaming expression. Besides, after the 
view of attribute values is constructed, it is immutable, so nothing can 
be added after the filtering is done.

> *) Dovetailing on the above two points, a flush bit for a given Log
> Record would be very nice as well.  99.999% of the time async logging
> is desired, but in the 0.001% of the time when a Log Record must get
> out to disk, chances are that one Log Record every blue moon is
> disproportionally valuable compared to the normal Log Record.  Having
> a flush() that doesn't return until the backend has fsync(2)'ed data
> would be really spiffy.
>
> BOOST_LOG_SEV(lg, warning)<<  "My message"<<  lg::flush;

As I already noted, your mileage is too biased, at least. I, personally, 
tend to use synchronous logging. But I do recognize that some kind of 
flushing ability would be nice in case of async logging.