Spring boot using log4j2 write log too slow

Question

I am using log4j2 in Spring Boot application to asyn logging. Here is my config log4j2-dev.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN" monitorInterval="30">
<Properties>
    <Property name="LOG_PATTERN">%d{yyyy-MM-dd HH:mm:ss.SSS} %highlight{%5p}--[%T-%-15.15t] [%-20X{serviceMessageId}]%-40.40c{1.} :%m%n%ex</Property>
</Properties>
<Appenders>
    <Console name="ConsoleAppender" target="SYSTEM_OUT"
        follow="true">
        <PatternLayout pattern="${LOG_PATTERN}" />
    </Console>
    <!-- Rolling File Appender -->
    <RollingFile name="FileAppender" fileName="logs/app.log"
        filePattern="logs/app-%d{yyyy-MM-dd}-%i.log">
        <PatternLayout>
            <Pattern>${LOG_PATTERN}</Pattern>
        </PatternLayout>
        <Policies>
            <SizeBasedTriggeringPolicy size="100MB" />
        </Policies>
        <DefaultRolloverStrategy max="10" />
    </RollingFile>
    <Kafka name="KafkaAppender" topic="ServiceCentrallog">
        <Property name="bootstrap.servers">10.2.16.2:9092,10.2.16.3:9092,10.2.16.4:9092</Property>
        <JSONLayout compact="true" properties="true">
            <KeyValuePair key="application"
                value="${bundle:application-dev:spring.application.name}" />
        </JSONLayout>
    </Kafka>
</Appenders>
<Loggers>
    <AsyncRoot level="info">
        <AppenderRef ref="ConsoleAppender" />
        <AppenderRef ref="FileAppender" />
        <AppenderRef ref="KafkaAppender" />
    </AsyncRoot>
</Loggers>

My BaseClass in Project

public abstract class BaseObject {
protected final org.apache.logging.log4j.Logger logger = LogManager.getLogger(getClass());

@Override
public String toString() {
    ObjectMapper mapper = new ObjectMapper();
    mapper.configure(SerializationFeature.FAIL_ON_EMPTY_BEANS, false);
    String jsonString = "";
    try {
        jsonString = mapper.writeValueAsString(this);
    } catch (JsonProcessingException e) {
        logger.error("BaseObject: ", e);
        jsonString = "Can't build json from object";
    }
    return jsonString;
}
}

Here is how I do to write log:

logger.info("Input: " + input.toString());
....
logger.info("output: " + Utils.toJson(restRes));

It work fine in normal case. But if I'm using Jmetter to send a lot of request (TOTAL: 7996, AVG: 98 message/s) I see that the logging is too slow, after stop sending requests about 1.5 minutes the logging is still continues and log files are still increasing in capacity.

I have searched a lot but still do not know how to speed up logging, or find out what's not reasonable in my configuration.

Answer 1

But if I'm using Jmetter to send a lot of request (TOTAL: 7996, AVG: 98 message/s) I see that the logging is too slow, after stop sending requests about 1.5 minutes the logging is still continues and log files are still increasing in capacity.

You are using asynch logging of Log4J2. Its intention is to not block the executing threads during logging operations. So if your application logs many things (7996*98 messages) in a couple of minutes, this behavior makes completely sense : messages are queued more and more and handling these until the last one will take time.

I have searched a lot but still do not know how to speed up logging, or find out what's not reasonable in my configuration.

1) Use synchronous logging will speed up your logging as it will use a blocking approach : the logging invocation will return only when the message would be effectively logged in the appender(s) but it will also affect the speed of your processings.

2) Don't use 3 appenders for this scenario (that is logging request/response):

<AsyncRoot level="info">
    <AppenderRef ref="ConsoleAppender" />
    <AppenderRef ref="FileAppender" />
    <AppenderRef ref="KafkaAppender" />
 </AsyncRoot>

It performs the log three times. It is a lot.
If you really need to log these information, log these in a single appender. You can achieve it easily with the filter feature (the MarkerFilter should be fine).
For example add the marker JSON_REQUEST_RESPONSE when you log and specify that only one of the appender logs it if present and the others don't log in any case :

<RollingFile name="FileAppender" fileName="logs/app.log"
    filePattern="logs/app-%d{yyyy-MM-dd}-%i.log">
  <!-- ACCEPT Marker-->
  <MarkerFilter marker="JSON_REQUEST_RESPONSE" onMatch="ACCEPT" />
  <...>
</RollingFile>

<Console name="ConsoleAppender" target="SYSTEM_OUT"
    follow="true">
  <!-- DENY Marker-->
  <MarkerFilter marker="JSON_REQUEST_RESPONSE" onMatch="DENY" />
  <...>
</Console>

3) Don't log so much in info() :

logger.info("Input: " + input.toString());
....
logger.info("output: " + Utils.toJson(restRes));

As a side note, don't use concatenation for logging because this can be expensive for nothing if the logger level doesn't match and that nothing is logged.
The lazy evaluated computation methods that takes a Supplier are better in this case :

logger.info("Input: {}", () -> input.toString());
....
logger.info("output: {}", () -> Utils.toJson(restRes));