METRON-2195 Add defensive log level checks when constructing logs is expensive #1473
Conversation
metron-platform/metron-common/src/main/java/org/apache/metron/common/utils/LazyLogger.java
Show resolved
Hide resolved
performance would benefit from it.
|
Since this is supposed to be a temporary fix pending Metron moving to SLF4J version 2.x, I've tried to minimise changes to those areas that would get a performance benefit from it, rather than doing a complete change over the the new API. Some classes where already shielding debug/trace statements by wrapping logging statements with "ifDebugEnabled()/ifTraceEnabled()" |
mmiklavc
left a comment
mmiklavc
left a comment
There was a problem hiding this comment.
+1 this looks solid to me. All my concerns have been addressed. Thanks @tigerquoll!
| * 2. If the log level is enabled, then all passed lamdas are called and parmeters are passed in the correct order | ||
| * 3. All methods call their wrapped messages correctly | ||
| */ | ||
| public class LazyLoggerImplTest { |
There was a problem hiding this comment.
Excellent work on the tests!
|
One ask - can you update your PR title to match the Jira description? Thanks! |
|
I missed one thing, which was requested by @ottobackwards on the Jira ticket - can you port my perf test into this PR? Don't have it run as part of a normal JUnit test run, include in the test code base similar to what was done with the HLLP example I provided on the Jira ticket. |
tigerquoll
changed the title
|
+1 |
2 participants
Contributor Comments
This PR illustrates a proof on concept for a logging wrapper that supports lazy argument evaluation. Lazy parameter evaluation technique is automatically supported in Java 8 native logging (which we don't use), and log4j 2.4+ (which we appear to use via SLF4J wrappers).
Unfortunately the lazy parameter evaluation provided by log4j 2.4+ is not currently exposed in the interfaces provided by the current SLF4J logging framework (support is scheduled for release with SLF4J 2.x) So to support lazy evaluation while maintaining use of the current SLF4j logging libraries a wrapper is required.
Rationale for lazy parameter evaluation
Even though the logging framework will not construct a string unless the logging level indicates a log message will be needed, all parameter arguments are still evaluated by the JVM as part of the standard java parameter passing process.
Lazy parameter evaluation is a useful technique for when some arguments are very expensive to calculate (eg. Serialising a collection object into a JSON string). When disabled logging calls are deeply nested under multiple levels of iteration, then there can be a real hidden cost to this unneeded parameter evaluation overhead.
This PR illustrates a technique of utilising a logging wrapper that supports lambdas as logging parameters. Typical scenarios where this could be used include code scenarios such as:
LOG.trace("Printed result of an expensive operation: {}", expensiveOperation().toString())Where expensiveOperation().toString is executed regardless of what logging level is enabled.
The suggested code to use with this wrapper would be
private static final LazyLogger LOG = LazyLoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
LOG.trace("Expensive operation only if trace logging enabled: {}", () -> expensiveOperation().toString()
As an example of usage
metron-platform/metron-writer/metron-writer-storm/src/main/java/org/apache/metron/writer/hdfs/HdfsWriter.javahas been updated to utilise this wrapper module.
Metron code has been analysed for logging usage, and those statements have been updated to use the lazy evaluation wrapper where it would be beneficial to performance.
The general guidance would be that any logging use that involves anything more than extremely basic string construction should use the lambda versions of the logging functions for performance reasons.
Error-level logging would be exempt from the requirement to use lambda versions of the logging functions due to error logging usually never being disabled, and thus no performance benefit is likely to come from forcing lazy parameter evaluation in this case.
If the lazy evaluation logging concept is approved I will add some unit testing before finalising the PR.
Pull Request Checklist
Thank you for submitting a contribution to Apache Metron.
Please refer to our Development Guidelines for the complete guide to follow for contributions.
Please refer also to our Build Verification Guidelines for complete smoke testing guides.
In order to streamline the review of the contribution we ask you follow these guidelines and ask you to double check the following:
For all changes:
For code changes:
Have you included steps to reproduce the behavior or problem that is being changed or addressed?
Have you included steps or a guide to how the change may be verified and tested manually?
Have you ensured that the full suite of tests and checks have been executed in the root metron folder via:
Have you written or updated unit tests and or integration tests to verify your changes?
If adding new dependencies to the code, are these dependencies licensed in a way that is compatible for inclusion under ASF 2.0?
Have you verified the basic functionality of the build by building and running locally with Vagrant full-dev environment or the equivalent?
For documentation related changes:
Have you ensured that format looks appropriate for the output in which it is rendered by building and verifying the site-book? If not then run the following commands and the verify changes via
site-book/target/site/index.html:Have you ensured that any documentation diagrams have been updated, along with their source files, using draw.io? See Metron Development Guidelines for instructions.
Note:
Please ensure that once the PR is submitted, you check travis-ci for build issues and submit an update to your PR as soon as possible.
It is also recommended that travis-ci is set up for your personal repository such that your branches are built there before submitting a pull request.