You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4cxx-dev@logging.apache.org by Tommi Mäkitalo <to...@epgmbh.de> on 2004/12/22 00:34:42 UTC
problem with logstream found
Hi,
logstream has indeed a problem: ios_base needs to be initialized. Normally
should happen by calling basic_ios<...>::init(), which is protected. Before
calling init the values are undefined. Width() returns on my machine
2507262709. This is not very useful to set up the wostingstream. The
example-program segfaults.
I think it would be better to derive logstream from ostream or do not derive
at all. I removed the base-class and the example-program works now. Here is
my patch.
I fixed also another bug: The stream must be cleared in flush even when
logging is disabled.
Tommi
Re: problem with logstream found
Posted by Christopher Smith <x...@xman.org>.
Tommi Maekitalo wrote:
> I personally feel, that the whole logstream-concept is broken by design. I use
> streams heavily, but don't use logstream. I have a macro, which encapsulates
> this whole formatting-stuff. I instantiate a ostringstream, when loging is
> enabled. Here is my macro-definition:
>
> #define CXXTOOLS_LOG(level, expr) \
> do { \
> if (getLogger()->isEnabledFor(::log4cxx::Level::level)) \
> { \
> std::ostringstream msg; \
> msg << expr; \
> getLogger()->log( \
> ::log4cxx::Level::level, \
> msg.str(), \
> LOG4CXX_LOCATION); \
> } \
> } while (false)
>
> #define log_fatal(expr) CXXTOOLS_LOG(FATAL, expr)
> #define log_error(expr) CXXTOOLS_LOG(ERROR, expr)
> #define log_warn(expr) CXXTOOLS_LOG(WARN, expr)
> #define log_info(expr) CXXTOOLS_LOG(INFO, expr)
> #define log_debug(expr) CXXTOOLS_LOG(DEBUG, expr)
>
>
> In my program I use:
>
> log_debug("the value is " << value << " hex=" << std::hex << value);
>
> I have the guarantee to get a fresh stream every time and when logging is
> disabled there is no stream-overhead at all.
What you are doing is the original behavior I was intending to
encapsulate with logging streams. If you look at my implementation it
has nearly the same effect, except that the stream is allocated on the
heap, and that it is not necessarily destroyed after the logging even is
sent (although the original implementation did have this as well). I set
this up based on what I feel was excellent feedback from Curt, as the
cost of constructing the ostream for each logging event is a bit on the
high side, and you'll want to mitigate it as much as possible.
> For log4cxx the best way to go is to offer a real ostream for users, who wants
> to use it. Everything else has its limitations. The standard-library is
> responsable for the overhead and not log4cxx.
Both Curt and I use the standard library for our streams (although I
wrote mine such that one could use one's own streams instead, something
that could also be done with Curt's if we wanted to).
--Chris
Re: problem with logstream found
Posted by Tommi Maekitalo <to...@epgmbh.de>.
Am Donnerstag, 23. Dezember 2004 03:14 schrieb Curt Arnold:
> On Dec 22, 2004, at 4:33 PM, Christopher Sm ith wrote:
...
> If I was doing:
>
> filestream << "We have: " << std::scientific << 3.1415926 << std::endl;
>
> At the end of the statement, I would expect that either an exception
> had been thrown (disk full, etc) or the filestream would have be left
> with the file stream using scientific notation.
>
> If I had used an explicit if, then obviously it would be silly for me
> to make an assertion about the state of the filestream after the if
> block. Since the explicit statement doesn't look conditional, the
> state of the stream after the statement should be the same as if I was
> writing to a filestream.
>
Good point. If someone writes multithreaded programs, he have to deal with
syncronisation. And if someone changes a attribute of a object, the
programmer should know, what he does.
I personally feel, that the whole logstream-concept is broken by design. I use
streams heavily, but don't use logstream. I have a macro, which encapsulates
this whole formatting-stuff. I instantiate a ostringstream, when loging is
enabled. Here is my macro-definition:
#define CXXTOOLS_LOG(level, expr) \
do { \
if (getLogger()->isEnabledFor(::log4cxx::Level::level)) \
{ \
std::ostringstream msg; \
msg << expr; \
getLogger()->log( \
::log4cxx::Level::level, \
msg.str(), \
LOG4CXX_LOCATION); \
} \
} while (false)
#define log_fatal(expr) CXXTOOLS_LOG(FATAL, expr)
#define log_error(expr) CXXTOOLS_LOG(ERROR, expr)
#define log_warn(expr) CXXTOOLS_LOG(WARN, expr)
#define log_info(expr) CXXTOOLS_LOG(INFO, expr)
#define log_debug(expr) CXXTOOLS_LOG(DEBUG, expr)
In my program I use:
log_debug("the value is " << value << " hex=" << std::hex << value);
I have the guarantee to get a fresh stream every time and when logging is
disabled there is no stream-overhead at all.
For log4cxx the best way to go is to offer a real ostream for users, who wants
to use it. Everything else has its limitations. The standard-library is
responsable for the overhead and not log4cxx.
Tommi
Re: problem with logstream found
Posted by Curt Arnold <ca...@apache.org>.
On Dec 23, 2004, at 3:02 PM, Christopher Smith wrote:
>> If I was doing:
>> filestream << "We have: " << std::scientific << 3.1415926 <<
>> std::endl;
>> At the end of the statement, I would expect that either an exception
>> had been thrown (disk full, etc) or the filestream would have be left
>> with the file stream using scientific notation.
>
> You would also expect that either an exception had been thrown or the
> filestream had written out "We have: " and written and end of line and
> done a flush. Now, which is more surprising: that the logstream might
> not have done all of that if the log level wasn't enabled, or that it
> did none of what I said, but all of what you said? It is probably one
> of those matter of perspective things, but to me it seems far more
> logical that all operator<< stuff either be a nop or not, rather than
> just some of it.
>
If I'm writing to a basic_ostream, I have no guarantees that any
effectual work is being done. I know that I'm formatting numbers into
streams and sending them appending them to something, but I have no
assurances that they are not being immediately discarded and have no
generic mechanism to ever check that anything really happened.
There is nothing wrong with someone writing a streambuf (I think that
is the right class, but forgive me if I'm wrong), that discarded
everything, or looked at characters after a new line and discarded
those that started with "DEBUG". That would not violate the contract
for a streambuf. What my logstream does is end up with the same
result, but without going through all the conversions the would precede
streambuf level filtering.
However, if I was doing streambuf level filtering, even if I totally
discarded everything, the manipulator would still change the state of
the stream.
Re: problem with logstream found
Posted by Christopher Smith <x...@xman.org>.
Curt Arnold wrote:
>
> On Dec 22, 2004, at 4:33 PM, Christopher Sm ith wrote:
>
>>
>> With the normal idiom for logstreams you would want different streams
>> for each log level which would avoid this issue entirely.
>
> What "normal" idiom? I'm not aware of any established patterns for
> using a STL stream-like interface for logging. If there are, references
> would be nice and we can add their ideas in the mix in addition to yours
> and mine.
I referenced log4cpp's streams. I've used others, although normally they
were internal tools and as such not available. As I recall, in the
log4cpp model a logstream is used only for a single logging event.
> What I was anticipating is that you would construct the logstream on
> entry to a method (or have it passed in as a reference) and use it for
> all log requests within the message body.
Okay, this was the original model I had envisioned when I suggested
logstreams in the first place, which was why I made the effort to avoid
constructing a stream unless one was actually needed (hence the use of
delegation instead of inheritence). I thought your feedback about having
to construct a new logstream being atypical suggested a model where
logstreams would be far more durable than just a single method call. If
were going with creating them once per method, I should think we'd want
the overhead of logging when disabled to be in the 40-50ns range rather
than the 1000ns+ range that I get when I construct an iostream.
> If I was doing:
>
> filestream << "We have: " << std::scientific << 3.1415926 << std::endl;
>
> At the end of the statement, I would expect that either an exception had
> been thrown (disk full, etc) or the filestream would have be left with
> the file stream using scientific notation.
You would also expect that either an exception had been thrown or the
filestream had written out "We have: " and written and end of line and
done a flush. Now, which is more surprising: that the logstream might
not have done all of that if the log level wasn't enabled, or that it
did none of what I said, but all of what you said? It is probably one of
those matter of perspective things, but to me it seems far more logical
that all operator<< stuff either be a nop or not, rather than just some
of it.
--Chris
Re: problem with logstream found
Posted by Curt Arnold <ca...@apache.org>.
On Dec 22, 2004, at 4:33 PM, Christopher Sm ith wrote:
>
> With the normal idiom for logstreams you would want different streams
> for each log level which would avoid this issue entirely.
>
What "normal" idiom? I'm not aware of any established patterns for
using a STL stream-like interface for logging. If there are,
references would be nice and we can add their ideas in the mix in
addition to yours and mine.
What I was anticipating is that you would construct the logstream on
entry to a method (or have it passed in as a reference) and use it for
all log requests within the message body. Are you suggesting creating
a logstream for each level that might be used within the method and
appropriately initializing them with your favorite options for
precision, width, etc? If you were doing that and wanted to pass
references to logstreams to called methods, you would have to pass 2 or
3 logstream&'s and hope that you didn't want to add another level.
> Regardless it would seem necessary to use something like iostate
> savers to ensure you didn't leave the stream in an unexpected state.
> For example, if you have two methods:
>
> Foo::bar() {
> logstream << getCount() << LOG4CXX_ENDMSG;
> //.. stuff
> }
>
> Foo::baz() {
> boost::io::ios_flags_saver ifs(logstream);
> logstream << std::hex << getPointer() << LOG4CXX_ENDMSG;
> //.. stuff
> }
Were you expecting to have logstream be an instance or static variable?
The actions on a log stream are not transactional, if you tried to
call Foo::bar() simultaneously with Foo::baz() (assuming that logstream
was a instance variable) you could get any number of permutations like:
logstream << std::hex << getCount << getPointer() << LOG4CXX_ENDMSG <<
LOG4CXX_ENDMSG;
which would have two logging requests one with count and pointer and a
second empty one.
>
> Now, if you remove ifs from Foo::baz(), then the format of getCount()
> in Foo::bar() will depend on whether Foo::baz() was called previously,
> which is even worse than it being impacted by what log level you have
> things set at. Once you are using ifs consistently, applying
> manipulators regardless of log levels just becomes a waste of CPU
> cycles and a source of additional code branching.
>
If code sections did not want to share conversion settings, they should
use separate logstream instances. Multiple logstreams can dispatch to
the same logger.
Say I was entering a method that did an iterative calculation and
wanted to consistently use a %e12.5 representation for floating point.
If manipulators were skipped if the current level was not at the
threshold, then I would have to do something like:
logstream logstream(log, Level::ALL);
logstream << std::scientific;
logstream.width(12);
logstream.precision(5);
logstream << Level::DEBUG;
> In general, if you weren't using logstreams and were instead manually
> using ostreams, it'd be very odd to have your I/O manipulators behave
> as you are suggesting. Which seems more natural:
>
> if (logger.isInfoEnabled()) {
> logstream << "We have: " << getCount() << " floats at: " << std::hex
> << getPointer() << LOG4CXX_ENDMSG;
> }
>
> or:
>
> if (logger.isInfoEnabled()) {
> logstream << "We have: " << getCount() << " floats at: ";
> }
>
> logstream << std::hex;
>
> if (logger.isInfoEnabled()) {
> logstream << getPointer() << LOG4CXX_ENDMSG;
> }
If I was doing:
filestream << "We have: " << std::scientific << 3.1415926 << std::endl;
At the end of the statement, I would expect that either an exception
had been thrown (disk full, etc) or the filestream would have be left
with the file stream using scientific notation.
If I had used an explicit if, then obviously it would be silly for me
to make an assertion about the state of the filestream after the if
block. Since the explicit statement doesn't look conditional, the
state of the stream after the statement should be the same as if I was
writing to a filestream.
> My point was though, regardless of which implementation we go with,
> the I/O manipulators can be setup to behave as per either approach.
> Indeed, if we *really* wanted to give people a choice of in the matter
> we could simply use a policy class. Heck, in theory we could make the
> "inheritence-vs-delegation" approach work that way as well, although
> that might be just a tad too unwieldy.
>
Re: problem with logstream found
Posted by Christopher Smith <x...@xman.org>.
Curt Arnold wrote:
> On Dec 21, 2004, at 7:12 PM, Christopher Smith wrote:
>>> If it isn't derived from std::ios_base, then manipulators like
>>> std::width etc can't be applied.
>>
>> Actually, I believe my delegation based approach to doing logger
>> streams did work just fine with IO maniplulators. It did ignore them
>> if the stream wasn't enabled just like everything else (which I think
>> is probably the right thing to do), but even that could be changed
>> with some template specializations for manipulators.
>
> We disagree on skipping manipulators applied when the threshold isn't
> reached. My opinion is that setting the threshold should only affect
> whether messages appear in the log or not, it should not affect the
> content of the messages. If you skip manipulators when the threshold
> isn't satisfied, then some aspect (say field width) on a particular
> message might vary with the threshold.
With the normal idiom for logstreams you would want different streams
for each log level which would avoid this issue entirely.
Regardless it would seem necessary to use something like iostate savers
to ensure you didn't leave the stream in an unexpected state. For
example, if you have two methods:
Foo::bar() {
logstream << getCount() << LOG4CXX_ENDMSG;
//.. stuff
}
Foo::baz() {
boost::io::ios_flags_saver ifs(logstream);
logstream << std::hex << getPointer() << LOG4CXX_ENDMSG;
//.. stuff
}
Now, if you remove ifs from Foo::baz(), then the format of getCount() in
Foo::bar() will depend on whether Foo::baz() was called previously,
which is even worse than it being impacted by what log level you have
things set at. Once you are using ifs consistently, applying
manipulators regardless of log levels just becomes a waste of CPU cycles
and a source of additional code branching.
In general, if you weren't using logstreams and were instead manually
using ostreams, it'd be very odd to have your I/O manipulators behave as
you are suggesting. Which seems more natural:
if (logger.isInfoEnabled()) {
logstream << "We have: " << getCount() << " floats at: " << std::hex <<
getPointer() << LOG4CXX_ENDMSG;
}
or:
if (logger.isInfoEnabled()) {
logstream << "We have: " << getCount() << " floats at: ";
}
logstream << std::hex;
if (logger.isInfoEnabled()) {
logstream << getPointer() << LOG4CXX_ENDMSG;
}
> I would be willing to have a cook-off on the implementation.
> However, the time is wrong to do that while the core is still flaky from
> the recent Unicode rework.
Agreed.
> I not even totally opposed to providing two different flavors of logging
> streams, though ideally we could keep the semantics as close as possible.
My point was though, regardless of which implementation we go with, the
I/O manipulators can be setup to behave as per either approach. Indeed,
if we *really* wanted to give people a choice of in the matter we could
simply use a policy class. Heck, in theory we could make the
"inheritence-vs-delegation" approach work that way as well, although
that might be just a tad too unwieldy.
--Chris
Re: problem with logstream found
Posted by Curt Arnold <ca...@apache.org>.
On Dec 21, 2004, at 7:12 PM, Christopher Smith wrote:
>> If it isn't derived from std::ios_base, then manipulators like
>> std::width etc can't be applied.
>
> Actually, I believe my delegation based approach to doing logger
> streams did work just fine with IO maniplulators. It did ignore them
> if the stream wasn't enabled just like everything else (which I think
> is probably the right thing to do), but even that could be changed
> with some template specializations for manipulators.
We disagree on skipping manipulators applied when the threshold isn't
reached. My opinion is that setting the threshold should only affect
whether messages appear in the log or not, it should not affect the
content of the messages. If you skip manipulators when the threshold
isn't satisfied, then some aspect (say field width) on a particular
message might vary with the threshold.
I would be willing to have a cook-off on the implementation. However,
the time is wrong to do that while the core is still flaky from the
recent Unicode rework. The stream based interface has the luxury of
not actually being compiled into log4cxx, it is just a convenient
header file that is provided and if log4cxx provides one, then nothing
to stop someone else from using there own and we can make radical
changes in the implementation as long as we keep the semantics
equivalent (however doing has its own difficulties).
I not even totally opposed to providing two different flavors of
logging streams, though ideally we could keep the semantics as close as
possible.
Re: problem with logstream found
Posted by Christopher Smith <x...@xman.org>.
Curt Arnold wrote:
> On Dec 21, 2004, at 5:34 PM, Tommi Mäkitalo wrote:
>> I think it would be better to derive logstream from ostream or do not
>> derive at all. I removed the base-class and the example-program works now.
>> Here is my patch.
>
> I had originally implemented this based on std::basic_ostream<logchar>
> but that was many times more expensive than the traditional log4cxx API
> calls when calls were below the threshold.
Note that at least on my system this change actually didn't produce that
significant of a performance improvement. Given that the requirements on
derived classes isn't defined in the language standard, perhaps it's not
worth the portability problems.
> If it isn't derived from
> std::ios_base, then manipulators like std::width etc can't be applied.
Actually, I believe my delegation based approach to doing logger streams
did work just fine with IO maniplulators. It did ignore them if the
stream wasn't enabled just like everything else (which I think is
probably the right thing to do), but even that could be changed with
some template specializations for manipulators.
--Chris
Re: problem with logstream found
Posted by Tommi Maekitalo <to...@epgmbh.de>.
Am Mittwoch, 22. Dezember 2004 01:45 schrieb Curt Arnold:
> On Dec 21, 2004, at 5:34 PM, Tommi Mäkitalo wrote:
> > Hi,
> >
> > logstream has indeed a problem: ios_base needs to be initialized.
> > Normally
> > should happen by calling basic_ios<...>::init(), which is protected.
> > Before
> > calling init the values are undefined. Width() returns on my machine
> > 2507262709. This is not very useful to set up the wostingstream. The
> > example-program segfaults.
>
> There was a conditional to call _Init for the VC implementation, guess
> it was also needed for GCC. I guess I can test this by creating a new
> unit test that creates a logstream and then gets its width expecting it
> to be zero.
"width" is not initialized at all. It might be zero even when not
initialized.basic_ios<...>::init() need to be called, but we cannot call it,
when derived from ios_base and if we derive from basic_ios, we need to
initialize a streambuf. I wouldn't try to call something non-standard like
_Init(). I prefer using standards. And as far as I understand it, it is not
possible to have a basic_ios-object without a streambuf, although some
implementations might have a way to do it.
>
> > I think it would be better to derive logstream from ostream or do not
> > derive
> > at all. I removed the base-class and the example-program works now.
> > Here is
> > my patch.
>
> I had originally implemented this based on std::basic_ostream<logchar>
> but that was many times more expensive than the traditional log4cxx API
> calls when calls were below the threshold. If it isn't derived from
> std::ios_base, then manipulators like std::width etc can't be applied.
> The sample test is pretty simple but my guess is the modifications
> would break tests/src/streamtestcase.cpp.
As Christopher wrote the manipulators work, because of delegating manipulators
to the underlying stream.
>
> > I fixed also another bug: The stream must be cleared in flush even when
> > logging is disabled.
>
> What was the symptom?
Whe the loglevel in decreased, so that the logger is disabled after the stream
buffers some output, LOG4CXX_ENDMSG suppresses output, but keeps the message
in the stream.
Re: problem with logstream found
Posted by Curt Arnold <ca...@apache.org>.
On Dec 21, 2004, at 5:34 PM, Tommi Mäkitalo wrote:
> Hi,
>
> logstream has indeed a problem: ios_base needs to be initialized.
> Normally
> should happen by calling basic_ios<...>::init(), which is protected.
> Before
> calling init the values are undefined. Width() returns on my machine
> 2507262709. This is not very useful to set up the wostingstream. The
> example-program segfaults.
There was a conditional to call _Init for the VC implementation, guess
it was also needed for GCC. I guess I can test this by creating a new
unit test that creates a logstream and then gets its width expecting it
to be zero.
>
> I think it would be better to derive logstream from ostream or do not
> derive
> at all. I removed the base-class and the example-program works now.
> Here is
> my patch.
I had originally implemented this based on std::basic_ostream<logchar>
but that was many times more expensive than the traditional log4cxx API
calls when calls were below the threshold. If it isn't derived from
std::ios_base, then manipulators like std::width etc can't be applied.
The sample test is pretty simple but my guess is the modifications
would break tests/src/streamtestcase.cpp.
>
> I fixed also another bug: The stream must be cleared in flush even when
> logging is disabled.
>
What was the symptom?