[
https://issues.apache.org/jira/browse/CASSANDRA-19632?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17848892#comment-17848892
]
Stefan Miklosovic edited comment on CASSANDRA-19632 at 5/23/24 10:48 AM:
-------------------------------------------------------------------------
I did some research on this and it is quite interesting read.
https://www.slf4j.org/faq.html#logging_performance
If we do this
{code}
logger.trace("abc" + obj + "def");
{code}
there is a performance penalty related to evaluating the argument.
When we do this:
{code}
logger.trace("abc {}", def);
{code}
this will evaluate {} only when we go to log on trace so it will check tracing
just once and it will evaluate {} at most once (if we indeed go to log).
Doing this
{code}
if (logger.isTracingEnabled()) logger.trace("abc" + obj + "def");
{code}
is the least performance-friendly, because it needs to evaluate if we go to log
on trace and if we do, then it will evaluate it for the second time in
logger.trace itself, plus it needs to construct the logging message before
doing so.
Doing this:
{code}
if (logger.isTracingEnabled()) logger.trace("abc {}", def);
{code}
will check if we go to trace at most twice and it will evaluate the placeholder
at most once.
I think that wrapping logger.trace with logger.isTracingEnabled() is necessary
only in case if
1) we do not use placeholders in the logging message, only string
concatenation, which would construct the logging message regardless of logging
or not, because it was not checked yet
2) if the number of placeholder arguments in logger.trace is bigger than 2.
For example, for 2)
{code}
logger.trace("abc {} def {}", obj1, obj2);
{code}
This will be OK. However this:
{code}
logger.trace("abc {} def {} ghi {}", obj1, obj2, obj3);
{code}
this will contain the hidden cost of constructing an object, Object[] ... with
these three parameters. Logging internals will create an object if the number
of placeholders is bigger than 2.
The cost of calling logger.isTracingEnabled is negligable, 1% of the actual
logging of the message but I think it is not necessary, as long as we make sure
that we are not using string concatenation upon message construction and as
long as we are not using more than 2 placeholders.
Also, it is important to check that it does not cost a lot to evaluate the
argument itself, as we hit that case in CASSANDRA-19429, for example
{code}
logger.trace("abc {}", thisIs.Hard.ToResolve())
{code}
Even we use a placeholder, if thisIs.Hard.ToResolve() takes a lot of resources,
that is not good and in that case it is preferable to wrap it in
isTracingEnabled(). There is no silver bullet, I think we need to just go case
by case by the rules I described and change it where it does not comply.
According to the docs, the alternative is also to use lambdas:
{code}
logger.trace("abc {}", () -> thisIs.Hard.ToResolve())
{code}
this will check if we go to log on trace level just once and it will evaluate
the placeholder if we indeed go to do that. I think this is the best solution.
I will try to go over the codebase to see where we are at currently.
EDIT: lambdas were added in SLF4J 2.0.0-alpha1
was (Author: smiklosovic):
I did some research on this and it is quite interesting read.
https://www.slf4j.org/faq.html#logging_performance
If we do this
{code}
logger.trace("abc" + obj + "def");
{code}
there is a performance penalty related to evaluating the argument.
When we do this:
{code}
logger.trace("abc {}", def);
{code}
this will evaluate {} only when we go to log on trace so it will check tracing
just once and it will evaluate {} at most once (if we indeed go to log).
Doing this
{code}
if (logger.isTracingEnabled()) logger.trace("abc" + obj + "def");
{code}
is the least performance-friendly, because it needs to evaluate if we go to log
on trace and if we do, then it will evaluate it for the second time in
logger.trace itself, plus it needs to construct the logging message before
doing so.
Doing this:
{code}
if (logger.isTracingEnabled()) logger.trace("abc {}", def);
{code}
will check if we go to trace at most twice and it will evaluate the placeholder
at most once.
I think that wrapping logger.trace with logger.isTracingEnabled() is necessary
only in case if
1) we do not use placeholders in the logging message, only string
concatenation, which would construct the logging message regardless of logging
or not, because it was not checked yet
2) if the number of placeholder arguments in logger.trace is bigger than 2.
For example, for 2)
{code}
logger.trace("abc {} def {}", obj1, obj2);
{code}
This will be OK. However this:
{code}
logger.trace("abc {} def {} ghi {}", obj1, obj2, obj3);
{code}
this will contain the hidden cost of constructing an object, Object[] ... with
these three parameters. Logging internals will create an object if the number
of placeholders is bigger than 2.
The cost of calling logger.isTracingEnabled is negligable, 1% of the actual
logging of the message but I think it is not necessary, as long as we make sure
that we are not using string concatenation upon message construction and as
long as we are not using more than 2 placeholders.
Also, it is important to check that it does not cost a lot to evaluate the
argument itself, as we hit that case in CASSANDRA-19429, for example
{code}
logger.trace("abc {}", thisIs.Hard.ToResolve())
{code}
Even we use a placeholder, if thisIs.Hard.ToResolve() takes a lot of resources,
that is not good and in that case it is preferable to wrap it in
isTracingEnabled(). There is no silver bullet, I think we need to just go case
by case by the rules I described and change it where it does not comply.
According to the docs, the alternative is also to use lambdas:
{code}
logger.trace("abc {}", () -> thisIs.Hard.ToResolve())
{code}
this will check if we go to log on trace level just once and it will evaluate
the placeholder if we indeed go to do that. I think this is the best solution.
I will try to go over the codebase to see where we are at currently.
> wrap tracing logs in isTraceEnabled across the codebase
> -------------------------------------------------------
>
> Key: CASSANDRA-19632
> URL: https://issues.apache.org/jira/browse/CASSANDRA-19632
> Project: Cassandra
> Issue Type: Improvement
> Components: Legacy/Core
> Reporter: Stefan Miklosovic
> Assignee: Stefan Miklosovic
> Priority: Normal
> Fix For: 5.x
>
> Time Spent: 10m
> Remaining Estimate: 0h
>
> Our usage of logger.isTraceEnabled across the codebase is inconsistent. This
> would also fix issues similar in e.g. CASSANDRA-19429 as [~rustyrazorblade]
> suggested.
> We should fix this at least in trunk and 5.0 (not critical though) and
> probably come up with a checkstyle rule to prevent not calling isTraceEnabled
> while logging with TRACE level.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
