Using log calls =============== There are several gotchas when logging. In particular, methods are called and strings are concatenated that have variables and objects can be constructed even if the logging level is more restrictive than the call. For instance, if the logging level is WARN, then a call like: log.trace("something {}", some_object.toString()) will cause some_object.toString() to be called, then the resulting string is passed to log.trace() where the log level is evaluated and the logging call may be aborted. Any method called explicitly as part of a logging call is executed regardless of whether the message will be logged or not. This can be very expensive as per measurements with Java Flight Recorder. It's particularly egregious when complex operations are performed for, say, debug or trace levels, which are rarely reported. Here are a few patterns that generate useless strings/objects: - log.info("some stuff " + some_object) will concatenate the some_object.toString() and create a new string. The only exception is if "some_object" is a literal string. - log.info("some stuff {}", object.method()) will execute the method. - log.info("some stuff {}", object.toString()) will execute the toString and then may throw the results away. log.info("some stuff{}", object) is safe, the object's toString() method is called only after the log/do not log decision has been made. ----------- NOTES: - If you're creating a logging call that has no choice but to do something expensive, surround it with "if (log.is*Enabled)". Validation will flag any situation where the level in the "if" clause does not match the level of the actual call. - Logging calls can take a bare exception, but do not use the braces if you want the stack trace! So log.info("stuff {}", exception) will not print the full stack, log.info("stuff ", exception) _will_ print the full stack. log.info("stuff {} ", some_object, exception) will print "stuff + the result of the object's toString() method" plus the full stack. If you're puzzled as to why so many logging calls don't have a matching number of curly-braces and parameters, this is usually why. - When slf4j supports lambdas in logging calls (log4j2 does now), we can use lambdas rather than "if log.is*Enabled". slf4j 2.0 will when released. This will probably mean this check has to be re-worked to avoid false flags - warn, error, and fatal level messages are NOT flagged for explicit, function calls, but will be flagged if they contain plusses that aren't simple concatenation. This last is something of a style check. - You can get into some pretty convolued consructs trying to pass some of these checks. Adding //logok, with or without spaces will cause the line to pass no matter what. Please use this hack sparingly and be conscientious about surrounding with 'if (log.is*Enabled)'. - String constants may be added with '+', but they _must_ be literal strings. The compiler is smart enough to concatenate them when compiling. For example: log.info("some {} "+ "more nonsense {}", object1, object2) is fine log.info("some{} " + " more nonsense " + object1, object2) is NOT fine (note the plus in front of object1). For a fuller discussion, see LUCENE-7788 and the other JIRAs linked from there.