Details
-
Improvement
-
Resolution: Fixed
-
Minor
-
1.7.30
-
Docker
Java: 1.8
Spring Boot: 2.2.5
Spring-Kafka. 2.4.4
SL4J: 1.7.30
-
major
Description
SLF4JLocationAwareLog converts input message Object into String on each invocation of logging method regardless if specific logging level is enabled.
This conversion is done using String.valueOf(message).
public void trace(Object message, Throwable t) { logger.log(null, FQCN, LocationAwareLogger.TRACE_INT, String.valueOf(message), null, t); }
Link to source: https://github.com/qos-ch/slf4j/blob/v_1.8.0_beta2/jcl-over-slf4j/src/main/java/org/apache/commons/logging/impl/SLF4JLocationAwareLog.java#L120
Passed in message object can typically be some wrapper object around of lazy lambda to produce message. Here is example where lambda is passed from spring kafka: https://github.com/spring-projects/spring-kafka/blob/v2.4.4.RELEASE/spring-kafka/src/main/java/org/springframework/kafka/core/DefaultKafkaProducerFactory.java#L596
Problem is that even though trace level is disabled, those messages do get constructed causing a performance penalty. In my concrete example on production, sampling showed that 20-45% of cpu time is spent here constructing message which won't even be logged.
My thinking is that it should be checked if logger is enabled for specific level before doing "expensive" operation of rendering message by converting it to string.
Pull request: https://github.com/qos-ch/slf4j/pull/244