| 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 //nowarn, 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. |