[log] Boost.Log Formal Review
(This is my first Boost library review so take it easy...)
Please explicitly state in your review whether the library should be accepted.
Yes. There are some concerns but I think it is very nearly complete, as far as my usage is concerned. These concerns are elicited in detail below but for now my three major ones are: - __LINE__, __FILE__ as attributes - Boost.DateTime formatting is sloooowwww - Ability to strip/compile out log messages in their entirety
What is your evaluation of the design?
I haven't applied it heavily yet but so far the design seems logical. Separating the sinks and sources provides good flexibility. I'm yet to delve into usage of the filters though.
What is your evaluation of the implementation?
I can't speak for the correctness of the implementation, but from a performance perspective, I've compared it to log4cxx (see the sourceforge thread Andrey has referred to) and it is comparable and/or better in most of my usages. Given the flexibility, I am prepared to pay for a little performance hits. A concern, which again Andrey has mentioned during this review, is the speed of Boost.DateTime formatting. From our comparisons, it is about 3-5x slower than log4cxx. Is it possible to have a bare-minimum date time formatter similar to log4cxx's implemented? I wrote a quick little wrapper using a customised strftime (for microseconds) with the most basic caching (which log4cxx's formatter uses) and performance was comparable.
What is your evaluation of the documentation?
For most the part, very good. Definitely sufficient/adequate for acceptance. The design and installation pages, etc, are extremely clear and easy to read. Personally, I would prefer a few more concrete examples. For example, (a minor one, I know) but how do you specify keywords via a settings file.
What is your evaluation of the potential usefulness of the library?
High. An efficient, highly functional and configurable logging library has much potential. I've found __LINE__ and __FILE__ missing as attributes. Andrey advised these are part of named_scope but the formatting is currently missing. Ideally - and I don't know if this is technically possible but - I would prefer these as just another attribute. Instead of requiring a BOOST_LOG_FUNCTION() call when you want to use them, you should be able to specify it as per usual, something a long the lines of: backend->set_formatter( fmt::format(%1% [%2%:%3%] %4%) % fmt::attr< SeverityLevel >("Severity") % fmt::attr< fmt::scope::file >("File") % fmt::attr< fmt::scope::line >("SrcLineNumber") % fmt::message() ); And then BOOST_LOG_SEV(...) << " a message" has the file and line attribute values already. Note, no need for BOOST_LOG_FUNCTION. With respect to compiling out the log messages: it would be desirable for security, code protection and/or performance if the ability to specify certain log records to be stripped out of the source code. A hack such as follows - which is obviously extremely inflexible - allows the users to define LOG_NTRACE to compile out all trace messages: # if defined (LOG_NTRACE) # define LOG_TRACE(logger, stream) (void(0)) ; # else # define LOG_TRACE(logger, stream) BOOST_LOG_SEV(logger, trace) << stream; # endif Something a lot smarter and flexible built into the library is desirable. Say, templated on your custom severity levels (or, indeed, any arbitrary attribute) and generating disable/enable macros.
Did you try to use the library? With what compiler? Did you have any problems?
Yes. gcc 4.3.3, msvc 9, and qcc/gcc 4.x.x (can't remember) on QNX. No problems.
How much effort did you put into your evaluation? A glance? A quick reading? In-depth study?
Initially, at the end of last year, I compared performance and functionality to log4cxx. However, for this review, I have had a quick read of the docs (not the code) and attempted integrating it for our purposes, about 4 hours worth.
Are you knowledgeable about the problem domain?
Not hugely. Middle-of-the-road. Neither here nor there. 5/10. Relatively average. A big thanks to Andrey for all his effort. Good luck with the acceptance! Cheers, Sam
On 03/17/2010 03:52 AM, sam.gundry@gmail.com wrote:
(This is my first Boost library review so take it easy...)
For example, (a minor one, I know) but how do you specify keywords via a settings file.
What keywords do you mean?
I've found __LINE__ and __FILE__ missing as attributes. Andrey advised these are part of named_scope but the formatting is currently missing. Ideally - and I don't know if this is technically possible but - I would prefer these as just another attribute. Instead of requiring a BOOST_LOG_FUNCTION() call when you want to use them, you should be able to specify it as per usual, something a long the lines of:
And then BOOST_LOG_SEV(...)<< " a message" has the file and line attribute values already. Note, no need for BOOST_LOG_FUNCTION.
Ah, I must have misunderstood you the first time. BOOST_LOG_FUNCTION saves the coordinates of the _scope_, but you need the coordinated of each log record. I see. Right now the simplest way to achieve it is to add them to your custom logging macro: #define LOG(lg, sev)\ BOOST_LOG_SEV(lg, sev) << __FILE__ << ":" << __LINE__ << " " A more graceful solution would involve adding those parameters as the logger-specific attributes and, perhaps, developing a logger feature to simplify their setting from the macro. I may develop such a feature and include it into the library.
With respect to compiling out the log messages: it would be desirable for security, code protection and/or performance if the ability to specify certain log records to be stripped out of the source code.
A hack such as follows - which is obviously extremely inflexible - allows the users to define LOG_NTRACE to compile out all trace messages:
#if defined (LOG_NTRACE) #define LOG_TRACE(logger, stream) (void(0)) ; #else #define LOG_TRACE(logger, stream) BOOST_LOG_SEV(logger, trace)<< stream; #endif
Something a lot smarter and flexible built into the library is desirable. Say, templated on your custom severity levels (or, indeed, any arbitrary attribute) and generating disable/enable macros.
I think, your simplistic solution is the most efficient, actually. It could be implemented by returning a null stream from the logging macro, but there's no guarantee that the logging code will be wiped out by the compiler.
----- Original Message ----- From: "Andrey Semashev" <andrey.semashev@gmail.com> To: <boost@lists.boost.org> Sent: Wednesday, March 17, 2010 8:29 PM Subject: Re: [boost] [log] Boost.Log Formal Review
On 03/17/2010 03:52 AM, sam.gundry@gmail.com wrote:
(This is my first Boost library review so take it easy...)
For example, (a minor one, I know) but how do you specify keywords via a settings file.
What keywords do you mean?
I've found __LINE__ and __FILE__ missing as attributes. Andrey advised these are part of named_scope but the formatting is currently missing. Ideally - and I don't know if this is technically possible but - I would prefer these as just another attribute. Instead of requiring a BOOST_LOG_FUNCTION() call when you want to use them, you should be able to specify it as per usual, something a long the lines of:
And then BOOST_LOG_SEV(...)<< " a message" has the file and line attribute values already. Note, no need for BOOST_LOG_FUNCTION.
Ah, I must have misunderstood you the first time. BOOST_LOG_FUNCTION saves the coordinates of the _scope_, but you need the coordinated of each log record. I see. Right now the simplest way to achieve it is to add them to your custom logging macro:
#define LOG(lg, sev)\ BOOST_LOG_SEV(lg, sev) << __FILE__ << ":" << __LINE__ << " "
A more graceful solution would involve adding those parameters as the logger-specific attributes and, perhaps, developing a logger feature to simplify their setting from the macro. I may develop such a feature and include it into the library.
With respect to compiling out the log messages: it would be desirable for security, code protection and/or performance if the ability to specify certain log records to be stripped out of the source code.
A hack such as follows - which is obviously extremely inflexible - allows the users to define LOG_NTRACE to compile out all trace messages:
#if defined (LOG_NTRACE) #define LOG_TRACE(logger, stream) (void(0)) ; #else #define LOG_TRACE(logger, stream) BOOST_LOG_SEV(logger, trace)<< stream; #endif
Something a lot smarter and flexible built into the library is desirable. Say, templated on your custom severity levels (or, indeed, any arbitrary attribute) and generating disable/enable macros.
I think, your simplistic solution is the most efficient, actually. It could be implemented by returning a null stream from the logging macro, but there's no guarantee that the logging code will be wiped out by the compiler.
maybe #if defined (LOG_NTRACE) #define LOG_TRACE(logger, stream) if (true); else logger #else #define LOG_TRACE(logger, stream) BOOST_LOG_SEV(logger, trace)<< stream; #endif I would like all the BOOST_LOG logger macros works this way. Best, Vicente
On 03/17/2010 11:04 PM, vicente.botet wrote:
maybe
#if defined (LOG_NTRACE) #define LOG_TRACE(logger, stream) if (true); else logger #else #define LOG_TRACE(logger, stream) BOOST_LOG_SEV(logger, trace)<< stream; #endif
I would like all the BOOST_LOG logger macros works this way.
That still leaves the streaming statements compiled. Although they will likely be optimized away, this doesn't eliminate the compilation cost and does not guarantee that no other traces of logging are left (such as string constants or functions).
----- Original Message ----- From: "Andrey Semashev" <andrey.semashev@gmail.com> To: <boost@lists.boost.org> Sent: Wednesday, March 17, 2010 9:31 PM Subject: Re: [boost] [log] Boost.Log Formal Review
On 03/17/2010 11:04 PM, vicente.botet wrote:
maybe
#if defined (LOG_NTRACE) #define LOG_TRACE(logger, stream) if (true); else logger #else #define LOG_TRACE(logger, stream) BOOST_LOG_SEV(logger, trace)<< stream; #endif
I would like all the BOOST_LOG logger macros works this way.
That still leaves the streaming statements compiled. Although they will likely be optimized away, this doesn't eliminate the compilation cost and does not guarantee that no other traces of logging are left (such as string constants or functions).
I think that we need to solve two issues when log is not needed. 1st : no time at all spent at runtime if log is not needed. 2nd : reduce the compilation time to a minimum log is not needed. The first is mandatory, the second is nice to have. Vicente
On 03/18/2010 12:37 AM, vicente.botet wrote:
maybe
#if defined (LOG_NTRACE) #define LOG_TRACE(logger, stream) if (true); else logger #else #define LOG_TRACE(logger, stream) BOOST_LOG_SEV(logger, trace)<< stream; #endif
I would like all the BOOST_LOG logger macros works this way.
That still leaves the streaming statements compiled. Although they will likely be optimized away, this doesn't eliminate the compilation cost and does not guarantee that no other traces of logging are left (such as string constants or functions).
I think that we need to solve two issues when log is not needed. 1st : no time at all spent at runtime if log is not needed. 2nd : reduce the compilation time to a minimum log is not needed.
The first is mandatory, the second is nice to have.
One of the first reasons for this request was to remove any trace of logging from the resulting binary (e.g., for security reasons). This includes the things I mentioned.
----- Original Message ----- From: "Andrey Semashev" <andrey.semashev@gmail.com> To: <boost@lists.boost.org> Sent: Wednesday, March 17, 2010 10:50 PM Subject: Re: [boost] [log] Boost.Log Formal Review
On 03/18/2010 12:37 AM, vicente.botet wrote:
maybe
#if defined (LOG_NTRACE) #define LOG_TRACE(logger, stream) if (true); else logger #else #define LOG_TRACE(logger, stream) BOOST_LOG_SEV(logger, trace)<< stream; #endif
I would like all the BOOST_LOG logger macros works this way.
That still leaves the streaming statements compiled. Although they will likely be optimized away, this doesn't eliminate the compilation cost and does not guarantee that no other traces of logging are left (such as string constants or functions).
I think that we need to solve two issues when log is not needed. 1st : no time at all spent at runtime if log is not needed. 2nd : reduce the compilation time to a minimum log is not needed.
The first is mandatory, the second is nice to have.
One of the first reasons for this request was to remove any trace of logging from the resulting binary (e.g., for security reasons). This includes the things I mentioned.
You lost me. Could you clarify which security reasons are you talking about? I expect the compiler after compiling the expression will not generate any code associated to if (true); else ..... Vicente
On 03/18/2010 01:07 AM, vicente.botet wrote:
maybe
#if defined (LOG_NTRACE) #define LOG_TRACE(logger, stream) if (true); else logger #else #define LOG_TRACE(logger, stream) BOOST_LOG_SEV(logger, trace)<< stream; #endif
I would like all the BOOST_LOG logger macros works this way.
That still leaves the streaming statements compiled. Although they will likely be optimized away, this doesn't eliminate the compilation cost and does not guarantee that no other traces of logging are left (such as string constants or functions).
I think that we need to solve two issues when log is not needed. 1st : no time at all spent at runtime if log is not needed. 2nd : reduce the compilation time to a minimum log is not needed.
The first is mandatory, the second is nice to have.
One of the first reasons for this request was to remove any trace of logging from the resulting binary (e.g., for security reasons). This includes the things I mentioned.
You lost me. Could you clarify which security reasons are you talking about?
If resources from logging statements are left in the compiled binary, they may be used to reverse engineer the application. The point of this proposal is to leave _absolutely_ nothing from the logging statements in the final binary.
I expect the compiler after compiling the expression will not generate any code associated to
if (true); else .....
The compiler will have to compile it anyway (perhaps, not to generate actual assembly, but surely to instantiate templates). It may be smart enough to remove that statement from the final code (most compilers are that smart). Then the linker may be smart enough to lose the unneeded string constants and functions that were only involved in the logging statement. But none of these optimizations are guaranteed to happen. And that's not overgeneralization, I did work with a compiler that did not drop unneeded functions from the final binary (not sure about strings, though). So the safest and most efficient way to achieve that is to wipe out the logging statement on the preprocessing stage.
sam.gundry@gmail.com wrote:
A concern, which again Andrey has mentioned during this review, is the speed of Boost.DateTime formatting. From our comparisons, it is about 3-5x slower than log4cxx. Is it possible to have a bare-minimum date time formatter similar to log4cxx's implemented? I wrote a quick little wrapper using a customised strftime (for microseconds) with the most basic caching (which log4cxx's formatter uses) and performance was comparable.
In our logging library, date/time formatting was likewise too sluggish. I now track midnight as a time_t, with the date string, and then compute the current time relative to midnight, do a little math, and the result is a very fast computation of the current time. Of course, I also have to determine if the current time is more than 24 hours since the cached midnight to detect when the cached values must be updated. _____ Rob Stewart robert.stewart@sig.com Software Engineer, Core Software using std::disclaimer; Susquehanna International Group, LLP http://www.sig.com IMPORTANT: The information contained in this email and/or its attachments is confidential. If you are not the intended recipient, please notify the sender immediately by reply and immediately delete this message and all its attachments. Any review, use, reproduction, disclosure or dissemination of this message or any attachment by an unintended recipient is strictly prohibited. Neither this message nor any attachment is intended as or should be construed as an offer, solicitation or recommendation to buy or sell any security or other financial instrument. Neither the sender, his or her employer nor any of their respective affiliates makes any warranties as to the completeness or accuracy of any of the information contained herein or that this message or any of its attachments is free of viruses.
Hi, ----- Original Message ----- From: "Stewart, Robert" <Robert.Stewart@sig.com> To: <boost@lists.boost.org> Sent: Thursday, March 18, 2010 4:18 PM Subject: Re: [boost] [log] Boost.Log Formal Review
sam.gundry@gmail.com wrote:
A concern, which again Andrey has mentioned during this review, is the speed of Boost.DateTime formatting. From our comparisons, it is about 3-5x slower than log4cxx. Is it possible to have a bare-minimum date time formatter similar to log4cxx's implemented? I wrote a quick little wrapper using a customised strftime (for microseconds) with the most basic caching (which log4cxx's formatter uses) and performance was comparable.
In our logging library, date/time formatting was likewise too sluggish. I now track midnight as a time_t, with the date string, and then compute the current time relative to midnight, do a little math, and the result is a very fast computation of the current time. Of course, I also have to determine if the current time is more than 24 hours since the cached midnight to detect when the cached values must be updated.
In Boost.Chrono there is a class t24_hours which is a view of a boost::chrono::duration<Rep, Period> providing accesors functions for number of days, hours, minutes, seconds and nanoseconds. Boost.Chrono provides also a formatter with a default format "%d days(s) %h:%m:%s.%n\n", where a.. %d : days b.. %h : hours c.. %m : minutes d.. %s : seconds e.. %n : nanoseconds The interface of basic_24_hours_formatter is quite specific to the needs of Stopwatches, but we can make an interface that is more adapted to your needs. More info at https://svn.boost.org/trac/boost/wiki/LibrariesUnderConstruction#Boost.Chron... The files related are: /boost/chrono/t24_hours.hpp /boost/chrono/t24_hours_formatter.hpp /libs/chrono/example/t24_hours_example.cpp I will appreciate if you can tell me what is missing and how the interface can change so you can get waht you need. Thanks, Vicente
participants (4)
-
Andrey Semashev -
sam.gundry＠gmail.com -
Stewart, Robert -
vicente.botet