Gradle precommit checks

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

Gradle precommit checks

Ilan Ginzburg
This might have been discussed previously but since I'm seeing this behavior...

Gradle precommit check does not allow code such as:
log.warn("Only in tree one: " + t1);

And forces changing it into:
log.warn("Only in tree one: {}", t1);

I do understand such constraints for debug level logs to not pay the concatenation cost if the log is not output (unless the log is inside an if block testing debug level), but for logs generally turned on (which I assume warn logs are), this is counter productive: the second form is less efficient during execution than the first one.

Ilan
Reply | Threaded
Open this post in threaded view
|

Re: Gradle precommit checks

Erick Erickson
Ilan:

Technically it may be true (although frankly I don’t know for sure), but practically at warn level any extra work isn’t worth the confusion.

 What do I mean by that? Well, we built up a huge debt with all sorts of debug and info and even trace messages that either concatenated strings or called methods or… See LUCENE-7788 for the amount of code that had to be changed.

So when I wrote the checker, I decided to flag all the concatenations in the code reasoning that for warn level messages, any extra work was so trivial that you couldn’t really measure it overall, and it’d be worth it to keep from “broken window" issues. I.e. someone sees log.warn(“whatever” + “whenever”) and thinks it’s OK to use that pattern for debug, trace or info.

I don’t particularly care if warn messages are a little inefficient on the theory that there should be so few of them that it’s not measurable.

All that said, this is absolutely a judgement call that I made trying to balance the technical with the practical. Given the number of people who contribute to the code, I think it’s worthwhile to keep certain patterns out of the code. Especially given how obscure logging costs are. The difference between 'log.trace(“message {}”, object.toString())’ and 'log.trace(“message {}”, object)’ for instance is unknown to a _lot_ of developers. Including me before I started looking at logging in general ;)

Best,
Erick

> On May 20, 2020, at 1:05 PM, Ilan Ginzburg <[hidden email]> wrote:
>
> This might have been discussed previously but since I'm seeing this behavior...
>
> Gradle precommit check does not allow code such as:
> log.warn("Only in tree one: " + t1);
>
> And forces changing it into:
> log.warn("Only in tree one: {}", t1);
>
> I do understand such constraints for debug level logs to not pay the concatenation cost if the log is not output (unless the log is inside an if block testing debug level), but for logs generally turned on (which I assume warn logs are), this is counter productive: the second form is less efficient during execution than the first one.
>
> Ilan


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Gradle precommit checks

Ilan Ginzburg
Thanks for your detailed response. I agree. Simplicity brings value.
And I agree that performance degradation of format method vs. native concat is negligible in the warn context. 

I need to look at the trace method to see the difference between the two calls (because I do believe that ("text" + obj) is equivalent to ("text" + obj.toString()). Is this assumption wrong?) 

Will run gradle precommit locally to stop being annoyed by these details.

Ilan


Le mer. 20 mai 2020 à 20:49, Erick Erickson <[hidden email]> a écrit :
Ilan:

Technically it may be true (although frankly I don’t know for sure), but practically at warn level any extra work isn’t worth the confusion.

 What do I mean by that? Well, we built up a huge debt with all sorts of debug and info and even trace messages that either concatenated strings or called methods or… See LUCENE-7788 for the amount of code that had to be changed.

So when I wrote the checker, I decided to flag all the concatenations in the code reasoning that for warn level messages, any extra work was so trivial that you couldn’t really measure it overall, and it’d be worth it to keep from “broken window" issues. I.e. someone sees log.warn(“whatever” + “whenever”) and thinks it’s OK to use that pattern for debug, trace or info.

I don’t particularly care if warn messages are a little inefficient on the theory that there should be so few of them that it’s not measurable.

All that said, this is absolutely a judgement call that I made trying to balance the technical with the practical. Given the number of people who contribute to the code, I think it’s worthwhile to keep certain patterns out of the code. Especially given how obscure logging costs are. The difference between 'log.trace(“message {}”, object.toString())’ and 'log.trace(“message {}”, object)’ for instance is unknown to a _lot_ of developers. Including me before I started looking at logging in general ;)

Best,
Erick

> On May 20, 2020, at 1:05 PM, Ilan Ginzburg <[hidden email]> wrote:
>
> This might have been discussed previously but since I'm seeing this behavior...
>
> Gradle precommit check does not allow code such as:
> log.warn("Only in tree one: " + t1);
>
> And forces changing it into:
> log.warn("Only in tree one: {}", t1);
>
> I do understand such constraints for debug level logs to not pay the concatenation cost if the log is not output (unless the log is inside an if block testing debug level), but for logs generally turned on (which I assume warn logs are), this is counter productive: the second form is less efficient during execution than the first one.
>
> Ilan


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Gradle precommit checks

Erick Erickson
log.info(“something {}”, object.toString());
and
log.info(“something {}”, object));

produce an equivalent log message at info level and above
I agree.

However, let’s say I’m at warn level and have the following call

log.info(“something {}”, object.toString()

the toString() method is executed _regardless_ of the logging level and the resulting
string is returned. This happens even if the message is not logged, in which case
whatever happened with in the toString() was useless work. The same is true for any
other method invoked as a parameter, thus the persnickety bits in the checking code
that basically say “if there are of parens outside strings in a log call, flag the call if
it’s not immediately preceded by an is###Enabled”.

And yes, “immediately preceded” is stupid-simple, it doesn’t look at an enclosing
block, I didn’t want to write a java parser ;). So you’ll see //logok as a bail-out

However, log.info(“something {}”, object)

figures out the log level first, then if the message is to be logged will call the
toString() method on the object. The work in toString is never wasted.

And toString() is simply an example. Any method call
is evaluated prior to determining whether the message should be logged or not.
So you’ll see a lot of what I frankly consider harmless method calls that just, say,
return an int or string still surrounded by an if (is###Enabled) block. It was just too
much work at this point to evaluate each and every method call to see if it was
“cheap enough” or not, quite apart from worrying about introducing errors. And Oh,
my aching head, I think there was even a case where the method call had a side
effect that affected execution so when it went into an if is###Enabled clause things
changed….

And that makes a certain amount of sense. The logging infrastructure can’t know
what a method call does, so has to make the call before determining whether to log
the message or not. You could have something as absurd as

log.info(“some message”, changeLoggingLevelToInfoRegardlessOfWhatItIsNow());

Absurd surely, but possible.

And I tried to put all this in 'gradlew helpValidateLogCalls’; anything that’s unclear there
we can change….

I arrived at these conclusions by looking a bit at the log4j2 docs and a bit by
tracing. If you find anything different than the above, please let me know and we’ll
address.

Best,
Erick

> On May 20, 2020, at 4:26 PM, Ilan Ginzburg <[hidden email]> wrote:
>
> Thanks for your detailed response. I agree. Simplicity brings value.
> And I agree that performance degradation of format method vs. native concat is negligible in the warn context.
>
> I need to look at the trace method to see the difference between the two calls (because I do believe that ("text" + obj) is equivalent to ("text" + obj.toString()). Is this assumption wrong?)
>
> Will run gradle precommit locally to stop being annoyed by these details.
>
> Ilan
>
>
> Le mer. 20 mai 2020 à 20:49, Erick Erickson <[hidden email]> a écrit :
> Ilan:
>
> Technically it may be true (although frankly I don’t know for sure), but practically at warn level any extra work isn’t worth the confusion.
>
>  What do I mean by that? Well, we built up a huge debt with all sorts of debug and info and even trace messages that either concatenated strings or called methods or… See LUCENE-7788 for the amount of code that had to be changed.
>
> So when I wrote the checker, I decided to flag all the concatenations in the code reasoning that for warn level messages, any extra work was so trivial that you couldn’t really measure it overall, and it’d be worth it to keep from “broken window" issues. I.e. someone sees log.warn(“whatever” + “whenever”) and thinks it’s OK to use that pattern for debug, trace or info.
>
> I don’t particularly care if warn messages are a little inefficient on the theory that there should be so few of them that it’s not measurable.
>
> All that said, this is absolutely a judgement call that I made trying to balance the technical with the practical. Given the number of people who contribute to the code, I think it’s worthwhile to keep certain patterns out of the code. Especially given how obscure logging costs are. The difference between 'log.trace(“message {}”, object.toString())’ and 'log.trace(“message {}”, object)’ for instance is unknown to a _lot_ of developers. Including me before I started looking at logging in general ;)
>
> Best,
> Erick
>
> > On May 20, 2020, at 1:05 PM, Ilan Ginzburg <[hidden email]> wrote:
> >
> > This might have been discussed previously but since I'm seeing this behavior...
> >
> > Gradle precommit check does not allow code such as:
> > log.warn("Only in tree one: " + t1);
> >
> > And forces changing it into:
> > log.warn("Only in tree one: {}", t1);
> >
> > I do understand such constraints for debug level logs to not pay the concatenation cost if the log is not output (unless the log is inside an if block testing debug level), but for logs generally turned on (which I assume warn logs are), this is counter productive: the second form is less efficient during execution than the first one.
> >
> > Ilan
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]