The if test beforehand should only be done if the log invocation is expected to
do unnecessary work, eg construct a varargs array or do some costly string
translation as part of the parameter construction to the log statement.
I would not want to encode as prescriptive list as the one proposed as the
facts (eg specifics of the API that may evolve) are what matter.
I’ll note, it is safer by far to bias towards the (if) guarded approach, as
performing two comparisons when trace is enabled is *not impactful* but
performing wasted work in normal operation on a hot path might be.
I am not certain this stuff is the kind of thing that’s urgent to include in
the code guide, really, except to perhaps note that it’s important to avoid
forcing unnecessary work on a hot path, and note that case of invoking a log
statement that might not reach a log endpoint.
> On 29 May 2024, at 22:38, David Capwell <dcapw...@apple.com> wrote:
>
>
>>
>> I saw a lot of cases like this:
>>
>> if (logger.isTraceEnabled())
>> logger.trace("a log message");
>>
>> and sometimes just:
>>
>> logger.trace("a log message");
>>
>> Why do we do it once like that and another time the other way?
>
> I remember years ago seeing perf numbers where the isTraceEnabled check was
> faster than calling trace directly, but time has moved on so that might no
> longer be true (and might have been before slf4j… its been awhile). Its a
> useful pattern when you are providing arguments to the string interpretation
> that is costly (such as converting longs to human sizes), but no clue if its
> still useful outside that case…
>
>> But if we are on TRACE, we actually check that _twice_
>
> To me it’s a trade off thing… you almost never enable tracing, so why
> optimize for that case rather than the normal case? If you have tracing
> often then yeah, you double lookup
>
>
>> Based on these findings, I went through the code and I have incorporated
>> these rules and I rewrote it like this:
>
>
> Makes sense to me.
>
>> Do these rules make sense to everybody and do you think this is something we
>> can stick to? This is quite hard to check-style so I am more for a written
>> consensus on a ML.
>
> If we do get enough people to say yes, then we should update our style
> guides. There are a lot of things in the style guides that are hard to check
> style (look at the section “Code Structure”, it has these types of rules)…
>
>> On May 29, 2024, at 2:24 PM, Štefan Miklošovič <stefan.mikloso...@gmail.com>
>> wrote:
>>
>> There is a ticket I have a mental block to merge (1). The way it happened is
>> that in CASSANDRA-19429 a user identified that there is a logging statement
>> which acquires a lock which slows down query execution. When reworked, under
>> CASSANDRA-19429, a reporter saw ridiculous performance gains on machines
>> like r8g.24xlarge and r7i.24xlarge (numbers in the ticket). The diff was
>> around 3x speed up which is quite hard to believe and myself with Jon Haddad
>> tried to replicate that but we were not able to do it reliably because our
>> machines were way smaller and we have not had resources to verify that.
>>
>> Anyway, that got me thinking ... If there are, potentially, so low-hanging
>> performance gains just by rewriting how we log, are not there any other
>> cases like that where we could see the performance gains too? Heck ... how
>> do we even log anyway? That got me rabbit hole-ing, I went through the
>> codebase and looked at what our logging on TRACE looks like and it resulted
>> in (1).
>>
>> The way we log is pretty inconsistent and it seems to me that various people
>> approach the logging by some "beliefs" they try to follow and I am not
>> completely sure where that comes from and whether other people look at it
>> the same way.
>>
>> I saw a lot of cases like this:
>>
>> if (logger.isTraceEnabled())
>> logger.trace("a log message");
>>
>> and sometimes just:
>>
>> logger.trace("a log message");
>>
>> Why do we do it once like that and another time the other way?
>>
>> When we do "if (logger.isTraceEnabled())" ..., if we are _not_ on TRACE, we
>> check it at most once. But if we are on TRACE, we actually check that
>> _twice_. The first time in "if" and the second time in "logger.trace()". But
>> that is not necessary, because logger.trace() is checking that anyway, we do
>> not need to wrap it. People probably think that if they just wrap it in
>> "if", it will be faster, but I do not see any meaningful differences when I
>> benchmark it and the documentation for slf4j tells the same. The difference
>> is negligible and in the realm of nanoseconds (!!!).
>>
>> On the other hand, logger.isTraceEnabled() is handy to use if there is some
>> heavy-weight object to log, like this
>>
>> if (logger.isTraceEnabled()
>> logger.trace("a log message {}",
>> object.takesALongTimeAndMemoryToConstructString());
>>
>> If it takes a considerable amount of time/memory to log, more than the
>> evaluation of isTraceEnabled itself, then it indeed makes sense to log it
>> like that.
>>
>> It does not make sense to wrap it in "if" when we do this:
>>
>> if (logger.isTraceEnabled())
>> logger.trace("a log message {}", object);
>>
>> The reason why is that logger.trace() itself evaluates if it is on TRACE or
>> not and "object.toString()" will be called _after_ we are 100% sure we are
>> indeed going to log it. So wrapping it is not necessary again and redundant.
>>
>> For cases like this, this is not necessary to wrap either:
>>
>> if (logger.isTraceEnabled())
>> logger.trace("a log message {}, {}", object1, object2);
>>
>> However, when there is a log with more than 2 arguments, like below,
>> according to the documentation, there is a hidden cost of constructing an
>> array of three objects. For one or two objects, no array, for 3 and more,
>> hidden object creation, even short-lived.
>>
>> if (logger.isTraceEnabled())
>> logger.trace("a log message {}, {}, {}", object1, object2, object3);
>>
>> This is wrong too:
>>
>> logger.trace("a log message " + object1 + " " + object2 + " " + object3);
>>
>> Because there is a cost of concatenating the strings and implicitly calling
>> .toString() on each object. It has to be evaluated every single time, even
>> though we are not going to log it on TRACE, because trace() needs to have a
>> string parameter regardless of whether we are logging or not.
>>
>> Based on these findings, I went through the code and I have incorporated
>> these rules and I rewrote it like this:
>>
>> 1) no wrapping in "if" if we are not logging more than 2 parameters.
>> 2) rewritten log messages to not contain any string concatenation but moving
>> it all to placeholders ({}).
>> 3) wrap it in "if" if we need to execute a method(s) on parameter(s) which
>> is resource-consuming.
>>
>> I realized I was not able to merge CASSANDRA-19632 because I just invented
>> these rules on my own without consulting that with anybody else and I do not
>> want to merge it and then people come after me that it is wrong or they
>> would question that.
>>
>> Do these rules make sense to everybody and do you think this is something we
>> can stick to? This is quite hard to check-style so I am more for a written
>> consensus on a ML.
>>
>> (1) https://issues.apache.org/jira/browse/CASSANDRA-19632
>
