logging performance and operator<<

Question

I contribute to an open source c++ application. In that application is all logging done with lines such as

if (Debug) std::cout << "MyClass | my debug message" << MyExpensiveStringConvertion() << std::endl;

being used to use more advanced logging framework (in other languages) I suggested using one of the existing frameworks such as boost, easylogginppp, whatever that does automatic formating and can be configured at runtime.

but I was replied that using "if (Debug)" has almost no overhead while writting

Log(debug) << "MyClass | my debug message" << MyExpensiveStringConvertion() 

requires both the computation of << operator and MyExpensiveStringConvertion() event when logging is disabled. Is this argument correct? if it is correct, should we care? Looks like most logging framework work that way so obviously most developers do not care

update: I understand if (Debug) form only require a simple bool test but I was expecting logging frameworks to implement all kinds of tricks to reduce cost like the "#define LOG(level) if (doDebug(level)) Log(level)" that Dietmar Kühl mentionned.

Answer 1

The key problem without the conditional in front of the output operation is that all the arguments are being evaluated. It is easy to short-circuit the actual output operations (just make sure that Log(debug) returns a stream with std::ios_base::failbit set in its state) but evaluating all arguments tends to involve an overhead you don't want to spent during logging. Of course, you could fix the notation for the logging using something like

#define LOG(level) if (doDebug(level)) Log(level)

... and then use

LOG(debug) << "MyClass | my debug message" << MyExpensiveStringConversion();

Answer 2

If you expect your app to use massive amounts of logging then the first option will make a (big) difference.
Otherwise, it doesn't really matter.

You can wrap the log function in macro so it's easily disabled at compile to time for benchmark purposes.

#ifdef LOG_ENABLED
    #define LOGSTR(x) do { \
                     debug && Log(debug) << x << MyExpensiveStringConvertion() \
         } while (0)
#else
    #define LOGSTR(x) (void)0
#endif

Answer 3

Thanks to all the posters I am know able to answer my own question.

The if (Debug) looks more efficient but most logging framework seems to be implemented in such a way that they in fact include the trick mentionnned by other posters

For example easylogging++ has DLOG and DCLOG that are both implemented as #define DCLOG(LEVEL, ...) if (_ELPP_DEBUG_LOG) CLOG(LEVEL, VA_ARGS)

and glog (google logging) has also a DLOG which also either checks a global variable or can be disabled at compile time. the Glog doc also says """ The conditional logging macros provided by glog (e.g., CHECK, LOG_IF, VLOG, ...) are carefully implemented and don't execute the right hand side expressions when the conditions are false. So, the following check may not sacrifice the performance of your application.

CHECK(obj.ok) << obj.CreatePrettyFormattedStringButVerySlow(); """

I guess boost logging also implements similar performance tricks

Answer 4

That is correct. A simple test against a boolean value (if (Debug)) is cheap and will skip over the expensive string 'Convertion' required by the unqualified Log(debug) statement. The code essentially amounts to:

test some_register, Debug
jne  skip_the_debug_crap
-- potentially lots of code here --

skip_the_debug_crap:
carry on...

Versus:

call ExpensiveStringConversion
call operator << with result (maybe, depends on what class is returned by conversion)
call operator << for whatever class Log(debug) evaluates to (with test for debug in callee)
clean up after function call
carry on...

(actually, this is somewhat simplified and not entirely accurate as calls to operator<< are L-R associative) You're looking at multiple calls every time, some expensive, whether or not the result ever needs to be logged. Also, if Log(debug) and ExpensiveStringConversion are not noexcept there will be some additional overhead required for potential stack unwinding.

Suggested solutions using compile-time macros means no startup or run-time changes possible to logging configuration.

On edit: the pseudo-assembly-like distillation (test, jne, call) is not meant to represent an x86 architecture