Introduction to the method of asynchronous printing of logback logs (code example)

This article brings you an introduction to the method of asynchronous printing of logback logs (code examples). It has certain reference value. Friends in need can refer to it. I hope it will be helpful to you.

Recently encountered a problem: the customer's server program occasionally responds too slowly to requests. By checking the log, it was found that the RSA signature verification code was executed for more than 20 seconds, while under normal circumstances it only takes Requires 16 milliseconds.

The RSA certificate is loaded when the server starts, and there is no problem of slow file reading. After looking at those lines of code, the most suspicious thing is the code for logback log printing.

Checked the production log configuration. The configuration in logback.xml is to generate a folder every month. The log files of the current month are all in the same folder. For example, the 201901 folder contains all the logs of January 2019. document. Each file is configured with a *.log.zip suffix and a size of 10MB, which means 10MB is a size-delimited file. The log printing class is configured with RollingFileAppender.

On 2019-1-30, more than 5,000 log files have been generated under the January 2019 folder, with an average of 167 log files per day.

So it is suspected that there are too many log files and the index file time is too long, which causes the code execution to slow down. In other words, if you want to doubt this, there is a premise: the log printing is synchronous, and the print log is called After the line of code is executed and written to the file, the business code will continue to be executed.

I asked several colleagues, and they all told me that log printing is performed asynchronously. Only one friend said it was synchronous. We all think that printing logs and writing files is time-consuming, and the logging framework should not write files synchronously. However, the fact is that if asynchronous printing is not configured, the log will be printed synchronously.

Breakpoint follow-up code found that the log is written to the file synchronously. Only when the configured appender is AsyncAppender, the log printing is printed asynchronously.

The following is the situation of synchronously printing logs:

logback.xml configuration:

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    ......
</appender>

<root level="DEBUG">
    <appender-ref ref="CONSOLE"/>
</root>

Execution code:

LogWork.debug("111111111111");
System.out.println("2222222222222");

Run result:

As you can see, the execution result is that the log of the log framework is printed and executed first. , and then execute the subsequent business code. So it's synchronous.

The following is how to configure the asynchronous printing log class:

The asynchronous printing log class AsyncAppender needs to reference an other log printing class, ASYNC only needs to print the log that needs to be printed Write to the defined cache queue, and then start a daemon thread to get the log from the queue and call the CONSOLE log printer to write the file. In this way, log printing is performed asynchronously.

logback.xml configuration:

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    ......
</appender>

<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <discardingThreshold>0</discardingThreshold>
    <queueSize>100</queueSize>
    <neverBlock>true</neverBlock>
    <appender-ref ref="CONSOLE"/>
</appender>

<root level="INFO">
    <appender-ref ref="ASYNC"/>
</root>

Execution code:

LogWork.debug("111111111111");
System.out.println("2222222222222");

Running result:

The running result shows that after the code that calls the log framework to print is executed, it just puts the log to be printed into the cache queue, and then continues to execute the following. code, so the following 222222 is printed first, and then 111111 is printed. The explanation is that after configuration, log printing works asynchronously.

Because the question at the beginning of the article raised the issue of synchronization of log printing, I did some research, but in the end I did not connect it with the problem encountered, because even if I knew that the log was printed synchronously, There is no way to explain why code execution is extremely slow for a few minutes occasionally. The evidence is insufficient, so no conclusion can be drawn.

The above is the detailed content of Introduction to the method of asynchronous printing of logback logs (code example). For more information, please follow other related articles on the PHP Chinese website!