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 <[email protected]> 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 <[email protected]> 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 <[email protected]> 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: [email protected]
> For additional commands, e-mail: [email protected]
>
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
