Erick Erickson created SOLR-11884:
-------------------------------------
Summary: find/fix inefficiencies in our use of logging
Key: SOLR-11884
URL: https://issues.apache.org/jira/browse/SOLR-11884
Project: Solr
Issue Type: Improvement
Security Level: Public (Default Security Level. Issues are Public)
Reporter: Erick Erickson
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.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
