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.

It is correct, with the fact that `MyExpensiveStringConver[s]ion()` is called being more important than the evaluation of `<<`. — Ry-, Nov 30 '14 at 18:25
Most logging frameworks are rubbish. That's why I've written my own one. — mip, Nov 30 '14 at 19:00
@doc Me too, although I run into annoying problems in production that maybe a proper framework would have already dealt with (e.g. log rolling fails because someone cloned the process and left an orphaned handle on my log file) — M.M, Nov 30 '14 at 23:58

score 5 · Answer 1 · answered Nov 30 '14 at 18:39

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();

that sounds like a good idea, but I was expected that kind of performance tricks to come out of the box in most logger frameworks, aren't they? — Olivier RD, Dec 01 '14 at 09:03

egur · Answer 2 · 2014-12-01T07:17:56.520

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

edited Dec 01 '14 at 07:17

answered Nov 30 '14 at 18:41

egur

7,830
2
27
47

1

It's better to define `#define LOGSTR(x) (void)0` in `#else` branch. Otherwise code like this one `if (something) LOGSTR("blahblah");` can be unpredictable (will give you compile error in most cases). +1 anyway. – mip Nov 30 '14 at 19:05
@doc `do { } while (0)` is the most robust way , [see here](http://stackoverflow.com/questions/154136/do-while-and-if-else-statements-in-c-c-macros) – M.M Nov 30 '14 at 23:56
Fixed according to helpful comments. – egur Dec 01 '14 at 07:18

score 2 · Accepted Answer · answered Dec 03 '14 at 18:50

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

frasnian · Answer 4 · 2014-11-30T23:50:39.577

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

logging performance and operator<<

4 Answers4