LoggingStreams

[Christopher Smith <x...@xman.org>]

Once again, as a former log4cpp user, I've identified something that 
log4cxx appears to be missing but which I'd like to have: LoggingStreams 
(or CategoryStreams as they are called in log4cpp).

These are streams that are tied to a particular Logger and priority 
level. This allows you to do something like:

LoggingStream foo(logger, WARN);
foo << "We got: " << anInt << " for a total of: " << anotherInt;
foo << " and an average of: " << aFloat << endl;

The advantage being that you don't need to an explicit "if 
(logger.isEnabled(WARN)) { ... }" wrapper around the formatting code. If 
the priority is disabled, then the LoggingStream just turns all 
operator<<()'s into noops, while otherwise it writes to a buffer, which 
it then flushes and sends on an endl or equivalent io manipulator. You 
get the efficiency of using the if() to check things, but the logging 
code doesn't have to take up as much screen realestate now.

I've written up my own implementation of this for log4cxx. It's not 
perfect, but it's getting there. I wanted to know what everyone else 
though about this idea.

--Chris

Re: LoggingStreams

[Christophe de VIENNE <cd...@alphacent.com>]

Tommi Maekitalo wrote:

>Am Dienstag, 5. Oktober 2004 16:55 schrieb Christopher Smith:
>  
>
>>No, this is the whole idea. The LoggingStream operator<< checks against
>>a constant bool called "enabled". If it's false, then it just returns
>>*this (this is what is meant when I say "noops", which isn't quite
>>accurate, but a fair reflection of what will happen once the optimizer
>>is done with the code). If it's true, *then* it does formatting.
>>
>>--Chris
>>    
>>
>Do you mean you don't use the normal operator<<(ostream&, whatever)?
>
>Then you have to declare a template-operator<<, so that every datatype with a 
>proper output-operator can be logged.
>
>template <typename T>
>::log4cxx::LoggingStream& operator<<(::log4cxx::LoggingStream& out, const T& 
>data)
>{
>  if (out.isEnabled())
>  {
>    out.getOStream() << data;
>  }
>  return out;
>  
>
> }

Thats the idea. It reminds me of enforcements classes by Andrei 
Alexandrescu and Petru Marginean 
(http://www.cuj.com/documents/s=8250/cujcexp2106alexandr/), which use 
this technique to evaluate and format the error messages if and only if 
a problem happen.


>To change loglevel you might define:
>::log4cxx::LoggingStream& operator<<(::log4cxx::LoggingStream& 
>out, ::log4cxx::LevelPtr& level)
>{
>  out.setLogLevel(level);
>}
>  
>
I'm not sure it is that necessary but why not.

Re: LoggingStreams

[Tommi Maekitalo <to...@epgmbh.de>]

Am Dienstag, 5. Oktober 2004 16:55 schrieb Christopher Smith:
> No, this is the whole idea. The LoggingStream operator<< checks against
> a constant bool called "enabled". If it's false, then it just returns
> *this (this is what is meant when I say "noops", which isn't quite
> accurate, but a fair reflection of what will happen once the optimizer
> is done with the code). If it's true, *then* it does formatting.
>
> --Chris
Do you mean you don't use the normal operator<<(ostream&, whatever)?

Then you have to declare a template-operator<<, so that every datatype with a 
proper output-operator can be logged.

template <typename T>
::log4cxx::LoggingStream& operator<<(::log4cxx::LoggingStream& out, const T& 
data)
{
  if (out.isEnabled())
  {
    out.getOStream() << data;
  }
  return out;
}

Yes I think it could work. Still out.isEnabled() (which should be inline) is 
called for each token to output, but this might be optimized away by the 
compiler.

I'm not sure, what the c++-standard tell about the type of std::endl, but if 
there is a specific type for it, the template can be specialized like this:

::log4cxx::LoggingStream& operator<<(::log4cxx::LoggingStream& out, const 
type_of_std__endl& data)
{
  out.doLogging();
}

To change loglevel you might define:
::log4cxx::LoggingStream& operator<<(::log4cxx::LoggingStream& 
out, ::log4cxx::LevelPtr& level)
{
  out.setLogLevel(level);
}

Tommi

Re: LoggingStreams

[Christopher Smith <x...@xman.org>]

Tommi Maekitalo wrote:

>Am Dienstag, 5. Oktober 2004 01:44 schrieb Christopher Smith:
>...
>  
>
>>LoggingStream foo(logger, WARN);
>>foo << "We got: " << anInt << " for a total of: " << anotherInt;
>>foo << " and an average of: " << aFloat << endl;
>>
>>The advantage being that you don't need to an explicit "if
>>(logger.isEnabled(WARN)) { ... }" wrapper around the formatting code. If
>>the priority is disabled, then the LoggingStream just turns all
>>operator<<()'s into noops, while otherwise it writes to a buffer, which
>>it then flushes and sends on an endl or equivalent io manipulator. You
>>get the efficiency of using the if() to check things, but the logging
>>code doesn't have to take up as much screen realestate now.
>>
>>    
>>
>This has a major performance-drawback. When processing operator<< your 
>compiler/system/whoever can't know, you will throw away the results. It has 
>to format all your output even if logging is disabled.
>  
>
No, this is the whole idea. The LoggingStream operator<< checks against 
a constant bool called "enabled". If it's false, then it just returns 
*this (this is what is meant when I say "noops", which isn't quite 
accurate, but a fair reflection of what will happen once the optimizer 
is done with the code). If it's true, *then* it does formatting.

--Chris

Re: LoggingStreams

[Curt Arnold <ca...@apache.org>]

On Oct 5, 2004, at 2:49 AM, Tommi Maekitalo wrote:

> Am Dienstag, 5. Oktober 2004 01:44 schrieb Christopher Smith:
> This has a major performance-drawback. When processing operator<< your
> compiler/system/whoever can't know, you will throw away the results. 
> It has
> to format all your output even if logging is disabled.
>

I think the intention was to overload the insertion operations so that 
they would be skipped when the logging threshold was not satisified,

Re: LoggingStreams

[Tommi Maekitalo <to...@epgmbh.de>]

Am Dienstag, 5. Oktober 2004 01:44 schrieb Christopher Smith:
...
>
> LoggingStream foo(logger, WARN);
> foo << "We got: " << anInt << " for a total of: " << anotherInt;
> foo << " and an average of: " << aFloat << endl;
>
> The advantage being that you don't need to an explicit "if
> (logger.isEnabled(WARN)) { ... }" wrapper around the formatting code. If
> the priority is disabled, then the LoggingStream just turns all
> operator<<()'s into noops, while otherwise it writes to a buffer, which
> it then flushes and sends on an endl or equivalent io manipulator. You
> get the efficiency of using the if() to check things, but the logging
> code doesn't have to take up as much screen realestate now.
>
This has a major performance-drawback. When processing operator<< your 
compiler/system/whoever can't know, you will throw away the results. It has 
to format all your output even if logging is disabled.


Tommi

Re: LoggingStreams

[Curt Arnold <ca...@apache.org>]

On Oct 4, 2004, at 7:50 PM, Christopher Smith wrote:

> Curt Arnold wrote:
>> Per the previous discussion on iostream-free log4cxx, this 
>> alternative API should be completely optional.  Ideally included in 
>> its own header (log4cxx/loggingstream.h?) and delegating to the 
>> primary API.
>
> Yup, I set it up entirely in a header.
>
>> A couple of issues:
>> 1. It would be good that logging streams weren't limited to one 
>> character type, so having a template like:
>> template<class Elem, class Tr = char_traits<Elem>> class 
>> log4cxx::basic_logging_stream : std::basic_ostream<Elem, Tr> {
>> }
>> would be good, though there might be a log4cxx::stream and 
>> log4cxx::wstream expansions of that template.
>
> Great minds think alike. ;-)
>
>> 2. The LOG4CXX_.* macros provide context values (__FILE__ and 
>> __LINE__ currently, may be expanded to include __func__).  How would 
>> you see adding that information into the logging stream?
>
> I used a macro for instantiating the stream. It passes in the file and 
> line number at the point of instantiation. So, the current model is 
> you would use a new stream instance for each log event you generate.

See 4.

>
>> 3. What would trigger the creation of a logging event?  My initial 
>> take is that it should be a call to flush() or close().
>
> I made an enum with it's own endl equivalent. I'm trying to figure out 
> how to use the standard iostream endl, but have hit a snag there.
>

std::endl is defined to call flush(), so constructing the message on 
flush seems appropriate,


>> 4. Would a logging stream be able to create multiple logging events?
>
> Right now no. However, I could restructure things so the "endl" is a 
> macro, which passes in __FILE__ and __LINE__. Then I could make the 
> flush also reset the stream and you could do multiple logging events. 
> I don't expect much of a win from this, and I haven't come up with a 
> way to do it which wouldn't add a bit of overhead.

If flush (not close) triggers a logging event, the a logging stream 
should be able to create multiple logging events or code that worked 
fine on normal std::ostream's would not work on log4cxx::stream.  I 
don't like redefining endl which would result in possible confusion 
when std::endl is used in some contexts and log4cxx::endl in others.

Inserting a LevelPtr seems a pretty intuitive way to change the level 
of a logging stream.  That is

logstream << log4cxx::Level::INFO << "This is an info msg" << endl;

log4j has a LocationInfo class that doesn't have an analog in log4cxx 
(but probably should).  If we define a core LocationInfo class, then 
the insertion of a LocationInfo could change the reported file and 
line.  A define like

#define LOG4CXX_ENDL log4cxx::LocationInfo(__FILE, __LINE__) << 
std::endl

would allow usage like:

logstream << "This is a msg " << LOG4CXX_ENDL;
logstream << "This is another msg " << LOG4CXX_ENDL;
logstream.close();




>
>> 5. When would the level be checked to determine if the stream is 
>> enabled.  My take would be on stream creation and after calls to 
>> flush.  If it were checked on each insertion operation, messages 
>> could look pretty funky if the configuration was modified while a 
>> message was being assembled.
>
> Right now I'm doing it at stream creation. I store it in a const 
> member variable, which allows the compiler to optimize all the checks 
> for each operator<< into a single check. If I did multiple events per 
> stream, I should think I'd probably have to do a check on each flush. 
> Perhaps not though. Maybe each instantion would correspond to a check, 
> and reuse of the stream would imply that dong a new check is not 
> necessary.

There are probably cases where you'd want to check at each flush and 
other cases where you'd like to bypass that overhead.  Maybe the 
behavior could be to only check on creation and any insertion of 
log4cxx::LevelPtr, so if you really wanted the level to be reevaluated 
you'd just insert the level again.

>
>> 6. Would the level of a logging stream be able to be modified?  It 
>> might be convenient, however you would not be able to change the 
>> level mid-way through construction of a message since earlier parts 
>> might have been no-op'd.  My take is that inserting a LevelPtr would 
>> imply a flush.
>
> I chose to go with the level being locked. Given that creating a 
> LoggingStream is cheap, and keeping things fixed allows the compiler 
> to make better optimization choices, I think this is the right way to 
> go.

Fixing the level of the stream might discourage changing the level of a 
message, especially if the logging stream was passed as a parameter.

Re: LoggingStreams

[Christopher Smith <x...@xman.org>]

Curt Arnold wrote:
> Per the previous discussion on iostream-free log4cxx, this alternative 
> API should be completely optional.  Ideally included in its own header 
> (log4cxx/loggingstream.h?) and delegating to the primary API.

Yup, I set it up entirely in a header.

> A couple of issues:
> 
> 1. It would be good that logging streams weren't limited to one 
> character type, so having a template like:
> 
> template<class Elem, class Tr = char_traits<Elem>> class 
> log4cxx::basic_logging_stream : std::basic_ostream<Elem, Tr> {
> }
> 
> would be good, though there might be a log4cxx::stream and 
> log4cxx::wstream expansions of that template.

Great minds think alike. ;-)

> 2. The LOG4CXX_.* macros provide context values (__FILE__ and __LINE__ 
> currently, may be expanded to include __func__).  How would you see 
> adding that information into the logging stream?

I used a macro for instantiating the stream. It passes in the file and 
line number at the point of instantiation. So, the current model is you 
would use a new stream instance for each log event you generate.

> 3. What would trigger the creation of a logging event?  My initial take 
> is that it should be a call to flush() or close().

I made an enum with it's own endl equivalent. I'm trying to figure out 
how to use the standard iostream endl, but have hit a snag there.

> 4. Would a logging stream be able to create multiple logging events?

Right now no. However, I could restructure things so the "endl" is a 
macro, which passes in __FILE__ and __LINE__. Then I could make the 
flush also reset the stream and you could do multiple logging events. I 
don't expect much of a win from this, and I haven't come up with a way 
to do it which wouldn't add a bit of overhead.

> 5. When would the level be checked to determine if the stream is 
> enabled.  My take would be on stream creation and after calls to flush. 
>  If it were checked on each insertion operation, messages could look 
> pretty funky if the configuration was modified while a message was being 
> assembled.

Right now I'm doing it at stream creation. I store it in a const member 
variable, which allows the compiler to optimize all the checks for each 
operator<< into a single check. If I did multiple events per stream, I 
should think I'd probably have to do a check on each flush. Perhaps not 
though. Maybe each instantion would correspond to a check, and reuse of 
the stream would imply that dong a new check is not necessary.

> 6. Would the level of a logging stream be able to be modified?  It might 
> be convenient, however you would not be able to change the level mid-way 
> through construction of a message since earlier parts might have been 
> no-op'd.  My take is that inserting a LevelPtr would imply a flush.

I chose to go with the level being locked. Given that creating a 
LoggingStream is cheap, and keeping things fixed allows the compiler to 
make better optimization choices, I think this is the right way to go.

--Chris

Re: LoggingStreams

[Curt Arnold <ca...@apache.org>]

On Oct 4, 2004, at 6:44 PM, Christopher Smith wrote:

> Once again, as a former log4cpp user, I've identified something that 
> log4cxx appears to be missing but which I'd like to have: 
> LoggingStreams (or CategoryStreams as they are called in log4cpp).
>
> These are streams that are tied to a particular Logger and priority 
> level. This allows you to do something like:
>
> LoggingStream foo(logger, WARN);
> foo << "We got: " << anInt << " for a total of: " << anotherInt;
> foo << " and an average of: " << aFloat << endl;
>
> The advantage being that you don't need to an explicit "if 
> (logger.isEnabled(WARN)) { ... }" wrapper around the formatting code. 
> If the priority is disabled, then the LoggingStream just turns all 
> operator<<()'s into noops, while otherwise it writes to a buffer, 
> which it then flushes and sends on an endl or equivalent io 
> manipulator. You get the efficiency of using the if() to check things, 
> but the logging code doesn't have to take up as much screen realestate 
> now.
>
> I've written up my own implementation of this for log4cxx. It's not 
> perfect, but it's getting there. I wanted to know what everyone else 
> though about this idea.
>

Per the previous discussion on iostream-free log4cxx, this alternative 
API should be completely optional.  Ideally included in its own header 
(log4cxx/loggingstream.h?) and delegating to the primary API.

A couple of issues:

1. It would be good that logging streams weren't limited to one 
character type, so having a template like:

template<class Elem, class Tr = char_traits<Elem>> class 
log4cxx::basic_logging_stream : std::basic_ostream<Elem, Tr> {
}

would be good, though there might be a log4cxx::stream and 
log4cxx::wstream expansions of that template.

2. The LOG4CXX_.* macros provide context values (__FILE__ and __LINE__ 
currently, may be expanded to include __func__).  How would you see 
adding that information into the logging stream?

3. What would trigger the creation of a logging event?  My initial take 
is that it should be a call to flush() or close().

4. Would a logging stream be able to create multiple logging events?

5. When would the level be checked to determine if the stream is 
enabled.  My take would be on stream creation and after calls to flush. 
  If it were checked on each insertion operation, messages could look 
pretty funky if the configuration was modified while a message was 
being assembled.

6. Would the level of a logging stream be able to be modified?  It 
might be convenient, however you would not be able to change the level 
mid-way through construction of a message since earlier parts might 
have been no-op'd.  My take is that inserting a LevelPtr would imply a 
flush.