find/fix inefficiencies in our use of logging

We've been looking at Solr using Flight Recorder and ran across some interesting things I'd like to discuss. Let's discuss general logging approaches here, then perhaps break out sub-JIRAs when we reach any kind of agreement.

1> Every log message generates a new Throwable, presumably to get things like line number, file, class name and the like. On a 2 minute run blasting updates this meant 150,000 (yes, 150K) instances of "new Throwable()".

 

See the section "Asynchronous Logging with Caller Location Information" at:

https://logging.apache.org/log4j/2.x/performance.html

I'm not totally sure changing the layout pattern will fix this in log4j 1.x, but apparently certainly should in log4j 2.

 

The cost of course would be that lots of our log messages would lack some of the information. Exceptions would still contain all the file/class/line information of course.

 

Proposal:

Change the layout pattern to, by default, NOT  include information that requires a Throwable to be created. Also include a pattern that could be un-commented to get this information back for troubleshooting.

 

--------------------

 

We generate strings when we don't need them. Any construct like

log.info("whatever " + method_that_builds_a_string + " : " + some_variable);

generates the string (some of which are quite expensive) and then throws it away if the log level is at, say, WARN. The above link also shows that parameterizing this doesn't suffer this problem, so anything like the above should be re-written as:

log.info("whatever {} : {} ", method_that_builds_a_string, some_variable);

 

The alternative is to do something like but let's make use of the built-in capabilities instead.

if (log.level >= INFO)

{    log.info("whatever " + method_that_builds_a_string + " : " + some_variable); }

etc.

This would be a pretty huge thing to fix all-at-once so I suppose we'll have to approach it incrementally. It's also something that, if we get them all out of the code should be added to precommit failures. In the meantime, if anyone who has the precommit chops could create a target that checked for this it'd be a great help in tracking all of them down, then could be incorporated in the regular precommit checks if/when they're all removed.

Proposal:

Use JFR or whatever to identify the egregious violations of this kind of thing (I have a couple I've found) and change them to parameterized form (and prove it works). Then see what we can do to move forward with removing them all through the code base.