[ 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: commits-unsubscr...@cassandra.apache.org For additional commands, e-mail: commits-h...@cassandra.apache.org