You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@zookeeper.apache.org by GitBox <gi...@apache.org> on 2019/12/30 21:30:45 UTC
[GitHub] [zookeeper] belugabehr opened a new pull request #1198:
ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
belugabehr opened a new pull request #1198: ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
URL: https://github.com/apache/zookeeper/pull/1198
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [zookeeper] belugabehr commented on a change in pull request #1198:
ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
Posted by GitBox <gi...@apache.org>.
belugabehr commented on a change in pull request #1198: ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
URL: https://github.com/apache/zookeeper/pull/1198#discussion_r362543292
##########
File path: zookeeper-contrib/zookeeper-contrib-loggraph/src/main/java/org/apache/zookeeper/graph/Log4JSource.java
##########
@@ -115,20 +115,16 @@ public Log4JSourceIterator(Log4JSource src, long starttime, long endtime, Filter
}
synchronized public long size() throws IOException {
- if (LOG.isTraceEnabled()) {
Review comment:
So in this particular case, it's am excellent candidate to be removed. The only difference here is that the static string "size() called" is pushed onto the stack before the call. That is immeasurably small. In return we get less code that is less error prone. There may also be some performance benefit from having a smaller code base when it comes to execution caching, so it may be faster with less code, though it's simply conjecture on my part.
"performing the call". It has to perform a call no matter what. It's either calling `isTraceEnabled()` or `trace()`. So that is a wash.
There is no auto-boxing in this case as it is passing a static string.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [zookeeper] maoling commented on a change in pull request #1198:
ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
Posted by GitBox <gi...@apache.org>.
maoling commented on a change in pull request #1198: ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
URL: https://github.com/apache/zookeeper/pull/1198#discussion_r362441854
##########
File path: zookeeper-contrib/zookeeper-contrib-loggraph/src/main/java/org/apache/zookeeper/graph/RandomAccessFileReader.java
##########
@@ -112,9 +112,7 @@ synchronized public int read(char[] cbuf, int off, int len) throws IOException {
}
synchronized public int read(byte[] buf, int off, int len) throws IOException {
- if (LOG.isTraceEnabled()) {
- LOG.trace("read(buf, off=" + off + ", len=" + len);
- }
+ LOG.trace("read(buf, off={}, len={}" off, len);
Review comment:
compile error?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [zookeeper] belugabehr commented on issue #1198: ZOOKEEPER-3670:
Clean Up Log Statements for SLF4J
Posted by GitBox <gi...@apache.org>.
belugabehr commented on issue #1198: ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
URL: https://github.com/apache/zookeeper/pull/1198#issuecomment-570926719
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 <no...@github.com>
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>
> .
>
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [zookeeper] eolivelli commented on a change in pull request #1198:
ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
Posted by GitBox <gi...@apache.org>.
eolivelli commented on a change in pull request #1198: ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
URL: https://github.com/apache/zookeeper/pull/1198#discussion_r362518606
##########
File path: zookeeper-contrib/zookeeper-contrib-loggraph/src/main/java/org/apache/zookeeper/graph/Log4JSource.java
##########
@@ -115,20 +115,16 @@ public Log4JSourceIterator(Log4JSource src, long starttime, long endtime, Filter
}
synchronized public long size() throws IOException {
- if (LOG.isTraceEnabled()) {
Review comment:
I am not sure this is good.
Usually this pattern prevents a waste of resources in invocation of the heavier method: pass parameters on the stack, performing the call, boxing primitives.
Although slf4j can be good in early existing I doubt that the impact is negligible, especially in hot paths
I would prefer to ensure to have a consistent usage of this pattern (if logenabled...log) instead of removing it
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [zookeeper] eolivelli commented on issue #1198: ZOOKEEPER-3670:
Clean Up Log Statements for SLF4J
Posted by GitBox <gi...@apache.org>.
eolivelli commented on issue #1198: ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
URL: https://github.com/apache/zookeeper/pull/1198#issuecomment-570267396
I am not talking about the particular case but the general case.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [zookeeper] belugabehr commented on issue #1198: ZOOKEEPER-3670:
Clean Up Log Statements for SLF4J
Posted by GitBox <gi...@apache.org>.
belugabehr commented on issue #1198: ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
URL: https://github.com/apache/zookeeper/pull/1198#issuecomment-578830176
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 <da...@gmail.com> 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 <no...@github.com>
> 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>
>> .
>>
>
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [zookeeper] eolivelli commented on issue #1198: ZOOKEEPER-3670:
Clean Up Log Statements for SLF4J
Posted by GitBox <gi...@apache.org>.
eolivelli commented on issue #1198: ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
URL: https://github.com/apache/zookeeper/pull/1198#issuecomment-570888432
>>> 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
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [zookeeper] anmolnar commented on issue #1198: ZOOKEEPER-3670:
Clean Up Log Statements for SLF4J
Posted by GitBox <gi...@apache.org>.
anmolnar commented on issue #1198: ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
URL: https://github.com/apache/zookeeper/pull/1198#issuecomment-578706266
@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).
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [zookeeper] belugabehr commented on issue #1198: ZOOKEEPER-3670:
Clean Up Log Statements for SLF4J
Posted by GitBox <gi...@apache.org>.
belugabehr commented on issue #1198: ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
URL: https://github.com/apache/zookeeper/pull/1198#issuecomment-570826470
@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
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [zookeeper] belugabehr commented on issue #1198: ZOOKEEPER-3670:
Clean Up Log Statements for SLF4J
Posted by GitBox <gi...@apache.org>.
belugabehr commented on issue #1198: ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
URL: https://github.com/apache/zookeeper/pull/1198#issuecomment-570926903
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 <da...@gmail.com> 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 <no...@github.com>
> 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>
>> .
>>
>
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [zookeeper] belugabehr commented on a change in pull request #1198:
ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
Posted by GitBox <gi...@apache.org>.
belugabehr commented on a change in pull request #1198: ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
URL: https://github.com/apache/zookeeper/pull/1198#discussion_r362543856
##########
File path: zookeeper-contrib/zookeeper-contrib-loggraph/src/main/java/org/apache/zookeeper/graph/RandomAccessFileReader.java
##########
@@ -112,9 +112,7 @@ synchronized public int read(char[] cbuf, int off, int len) throws IOException {
}
synchronized public int read(byte[] buf, int off, int len) throws IOException {
- if (LOG.isTraceEnabled()) {
- LOG.trace("read(buf, off=" + off + ", len=" + len);
- }
+ LOG.trace("read(buf, off={}, len={}" off, len);
Review comment:
Woops. That's embarrassing. Must have accidentally hit a few key strokes there. Thanks for pointing it out. I've update the PR to fix this.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services
[GitHub] [zookeeper] belugabehr commented on issue #1198: ZOOKEEPER-3670:
Clean Up Log Statements for SLF4J
Posted by GitBox <gi...@apache.org>.
belugabehr commented on issue #1198: ZOOKEEPER-3670: Clean Up Log Statements for SLF4J
URL: https://github.com/apache/zookeeper/pull/1198#issuecomment-578806029
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 <no...@github.com> 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>
> .
>
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services