apache
ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
@eolivelli I just ran some JMH tests against logging with DEBUG disabled:
Benchmark Mode Cnt Score Error Units
Driver.logGuardsOne thrpt 5 246381456.066 ± 4270444.744 ops/s
Driver.logGuardsThree thrpt 5 244367801.436 ± 9044060.466 ops/s
Driver.logGuardsTwo thrpt 5 244778290.638 ± 5819192.601 ops/s
Driver.logParamsOne thrpt 5 243305350.620 ± 7246975.995 ops/s
Driver.logParamsThree thrpt 5 247552934.755 ± 9858216.394 ops/s
Driver.logParamsTwo thrpt 5 246506607.488 ± 16678526.453 ops/s
No real measurable difference between the two versions:
// Logging Guard (logGuardsOne)
if (LOGGER.isDebugEnabled()) {
LOGGER.debug("My application name is: " + varApplicationName);
}
// Params Logging (logParamsOne)
LOGGER.debug("My application name is: {}", varApplicationName);
You can check out the code here: https://github.com/belugabehr/doesitperf
There is no auto-boxing in this case as it is passing a static string
I see all of your points, and probably the escape analysis performed by the jvm sometimes is able to skip doing things (allocating variables, skipping useless branches)
My point is more about having a consistent way of using the logger. The 'if' guard helps in skipping useless work especially for more complex log lines.
We could say 'use the guard only in complex cases' but it is not automatic to make this decision
In my opinion a good trade-off is to use if-guards only for debug/trace statements, with the assumption that usually 'info' statements are always enabled and they do not appear in hot paths.
And use always parameters, it is always better
Hello and thank you for the discussion.
I think the reason parameterized logging was introduced in the first place was to avoid having to use guards and that it should be the default. No one wants to have to add boilerplate code guards every time they want to log something. Code reviews should help guide when the exception is made.
It's a bit backwards to suggest that INFO and higher logging should use parameterized logging. I personally find it easy to read, and I appreciate the consistency with DEBUG messages, but it would technically be more perfomant to use the normal string concatenation when building a INFO log message. Otherwise the framework needs to first locate the anchors and then splice in the variables. This is needless overhead if the log message is always going to be emitted anyway.
On Sun, Jan 5, 2020, 3:12 AM Enrico Olivelli [email protected] wrote:
There is no auto-boxing in this case as it is passing a static string
I see all of your points, and probably the escape analysis performed by the jvm sometimes is able to skip doing things (allocating variables, skipping useless branches)
My point is more about having a consistent way of using the logger. The 'if' guard helps in skipping useless work especially for more complex log lines.
We could say 'use the guard only in complex cases' but it is not automatic to make this decision
In my opinion a good trade-off is to use if-guards only for debug/trace statements, with the assumption that usually 'info' statements are always enabled and they do not appear in hot paths.
And use always parameters, it is always better
— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/apache/zookeeper/pull/1198?email_source=notifications&email_token=AC766E7ADQZDN7DLW3S4DWTQ4GI6HA5CNFSM4KBQKQ4KYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEIDRB4A#issuecomment-570888432, or unsubscribe https://github.com/notifications/unsubscribe-auth/AC766E5E6KMWWDOL7FC7JT3Q4GI6HANCNFSM4KBQKQ4A .
And if you check the docs, parameterized logging is only discussed in the context of DEBUG logging.
http://www.slf4j.org/faq.html#logging_performance
On Sun, Jan 5, 2020, 11:28 AM David Mollitor [email protected] wrote:
Hello and thank you for the discussion.
I think the reason parameterized logging was introduced in the first place was to avoid having to use guards and that it should be the default. No one wants to have to add boilerplate code guards every time they want to log something. Code reviews should help guide when the exception is made.
It's a bit backwards to suggest that INFO and higher logging should use parameterized logging. I personally find it easy to read, and I appreciate the consistency with DEBUG messages, but it would technically be more perfomant to use the normal string concatenation when building a INFO log message. Otherwise the framework needs to first locate the anchors and then splice in the variables. This is needless overhead if the log message is always going to be emitted anyway.
On Sun, Jan 5, 2020, 3:12 AM Enrico Olivelli [email protected] wrote:
There is no auto-boxing in this case as it is passing a static string
I see all of your points, and probably the escape analysis performed by the jvm sometimes is able to skip doing things (allocating variables, skipping useless branches)
My point is more about having a consistent way of using the logger. The 'if' guard helps in skipping useless work especially for more complex log lines.
We could say 'use the guard only in complex cases' but it is not automatic to make this decision
In my opinion a good trade-off is to use if-guards only for debug/trace statements, with the assumption that usually 'info' statements are always enabled and they do not appear in hot paths.
And use always parameters, it is always better
— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/apache/zookeeper/pull/1198?email_source=notifications&email_token=AC766E7ADQZDN7DLW3S4DWTQ4GI6HA5CNFSM4KBQKQ4KYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEIDRB4A#issuecomment-570888432, or unsubscribe https://github.com/notifications/unsubscribe-auth/AC766E5E6KMWWDOL7FC7JT3Q4GI6HANCNFSM4KBQKQ4A .
@belugabehr I also understand your points, but I would stick to what @eolivelli is saying: let's stay consistent in terms of coding: use isEnabled() guards for debug/trace statement and always use parameters. Based on my experiences consistent coding guidelines are the least error prone, no matter how accurate our code reviews are (they are not).
We'll have to agree to disagree on this point. Guards are just boilerplate and add a lot of noise to the codebase. I'd say that it's better to have clean consice code and if there's some sort of performance hit from a bad logging statement (very unlikely that a few improper statement would cause measurable trouble), it can be fixed after a performance test identifies it as being an issue. Not to mention, it will require policing either way, to enforce guards or no guards in code reviews, so that comes into play either way. If you want an example of a well written (and fast!) application, take a look at Apache Kafka code base.
Just note that there is no particular benefit to using both guards and parameters. In terms of debug logging performance, it is better to avoid having to scan the message looking for anchors and just pass the raw message string.
On Mon, Jan 27, 2020, 3:28 AM Andor Molnár [email protected] wrote:
@belugabehr https://github.com/belugabehr I also understand your points, but I would stick to what @eolivelli https://github.com/eolivelli is saying: let's stay consistent in terms of coding: use isEnabled() guards for debug/trace statement and always use parameters. Based on my experiences consistent coding guidelines are the least error prone, no matter how accurate our code reviews are (they are not).
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/apache/zookeeper/pull/1198?email_source=notifications&email_token=AC766E5RS2TCMRVMPVDKWPDQ73APFA5CNFSM4KBQKQ4KYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEJ7FWWQ#issuecomment-578706266, or unsubscribe https://github.com/notifications/unsubscribe-auth/AC766E5AEIIT2WWO67CSFKLQ73APFANCNFSM4KBQKQ4A .
Not to mention how many times I've seen the following:
if (log.isDebugEnabled()) { log.trace("msg"); }
On Mon, Jan 27, 2020, 7:36 AM David Mollitor [email protected] wrote:
We'll have to agree to disagree on this point. Guards are just boilerplate and add a lot of noise to the codebase. I'd say that it's better to have clean consice code and if there's some sort of performance hit from a bad logging statement (very unlikely that a few improper statement would cause measurable trouble), it can be fixed after a performance test identifies it as being an issue. Not to mention, it will require policing either way, to enforce guards or no guards in code reviews, so that comes into play either way. If you want an example of a well written (and fast!) application, take a look at Apache Kafka code base.
Just note that there is no particular benefit to using both guards and parameters. In terms of debug logging performance, it is better to avoid having to scan the message looking for anchors and just pass the raw message string.
On Mon, Jan 27, 2020, 3:28 AM Andor Molnár [email protected] wrote:
@belugabehr https://github.com/belugabehr I also understand your points, but I would stick to what @eolivelli https://github.com/eolivelli is saying: let's stay consistent in terms of coding: use isEnabled() guards for debug/trace statement and always use parameters. Based on my experiences consistent coding guidelines are the least error prone, no matter how accurate our code reviews are (they are not).
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/apache/zookeeper/pull/1198?email_source=notifications&email_token=AC766E5RS2TCMRVMPVDKWPDQ73APFA5CNFSM4KBQKQ4KYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEJ7FWWQ#issuecomment-578706266, or unsubscribe https://github.com/notifications/unsubscribe-auth/AC766E5AEIIT2WWO67CSFKLQ73APFANCNFSM4KBQKQ4A .
@eolivelli Wondering if you could take a look at this again with fresh eyes before 3.7.0
@belugabehr thanks for the reminder that also thanks for bringing this point forward.
I am still convinced that it is better to leave guards and enforce a "best practice" (as @anmolnar said).
Calling methods is still "doing something", that is more costly than "not doing anything", in fact the guard is still a method call, but without arguments and probably it is something that can be optimised better by the JVM.
but the main point is that having a consistent style that protects the codebase from stupid errors that could cost lot of resources in production, like leaking some call to a toString() method of a big object is a value.
that said, simply I am not blocking this patch, but I am not sponsoring it, if other people in the community are willing to sponsor this approach than I will be happy to participate in the discussion with 'open mind' again, thanks for bringing up this topic to the community
One way to look for a sponsor is to write to [email protected] and start a longer discussion (if we already haven't started it :-) )