logback asynchronous output log explanation

preface

Logback should be the most popular log printing framework at present. After all, the default integrated log framework in Spring Boot is also logback. In the actual project development process, we often encounter the problem of reducing program concurrency and QPS due to printing a large number of logs. This problem can be solved to a great extent through logback asynchronous log output.

1, What is an Appender?

Official logback documentation: https://logback.qos.ch/manual/appenders.html

logback Chinese document

Official introduction:

Logback delegates the task of writing log events to the component named Appenders, which must implement ch.qos logback. core. The interface of the appender.
Simply put, an Appender is a component used to handle log output events under the logback framework.

The core methods of the Appender interface are as follows:

package ch.qos.logback.core;
  
import ch.qos.logback.core.spi.ContextAware;
import ch.qos.logback.core.spi.FilterAttachable;
import ch.qos.logback.core.spi.LifeCycle;
  

public interface Appender<E> extends LifeCycle, ContextAware, FilterAttachable {

  public String getName();
  
  public void setName(String name);

 //Core method: processing log events
  void doAppend(E event);
  
}

The doAppend() method is the most important method in the logback framework. It is responsible for outputting log events to the appropriate output device in the appropriate format.

2, Appender class diagram

Description:
Outputstreamapender is a superclass of the other three add-on programs, namely ConsoleAppender and FileAppender, which is a superclass of RollingFileAppender. The next figure illustrates the class diagram of outputstreamapender and its subclasses.

1. Console log output ConsoleAppender

Configuration example:

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%-4relative [%thread] %-5level %logger{35} - %msg %n</pattern>
    </encoder>
  </appender>
  <root level="DEBUG">
       <appender-ref ref="STDOUT" />
  </root>
  </configuration>

Description:
Console log output is mainly used in the development environment. For example, when developing in IDEA, you can clearly and intuitively see the running log on the console, which is more convenient for program debugging. When the application is published to the test environment and production environment, it is recommended to turn off the console log output to improve the throughput of log output and reduce unnecessary performance overhead.

2. Single log file output FileAppender

Configuration example:

<configuration>
  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <!-- Log file name -->
    <file>testFile.log</file>
    <!-- Whether to append output -->
    <append>true</append>
    <!-- Refresh now, set to false Can improve log throughput -->
    <immediateFlush>true</immediateFlush>
    <encoder>
     <!-- Log output format -->
      <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
    </encoder>
  </appender>
        
  <root level="DEBUG">
    <appender-ref ref="FILE" />
  </root>
</configuration>

Disadvantages:
Using a single log file to output logs can easily cause the volume of the log file to expand all the time, which is not conducive to the management and viewing of the log file. It is rarely used.

3. Rolling log file output RollingFileAppender

Configuration example:

<configuration>
  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <!-- Log file name -->
    <file>logFile.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <!-- Rolling generation of historical log files by day -->
      <fileNamePattern>logFile.%d{yyyy-MM-dd}.log</fileNamePattern>

      <!-- Number of days and capacity of historical log file-->
      <maxHistory>30</maxHistory>
      <totalSizeCap>3GB</totalSizeCap>
    </rollingPolicy>

    <encoder>
      <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
    </encoder>
  </appender> 

  <root level="DEBUG">
    <appender-ref ref="FILE" />
  </root>
</configuration>

Description:
Configure the rolling generation policy of log files, as well as the number of days and total capacity of historical log files through rollingPolicy,
It is the most recommended log output method for test environment and production environment.

3, Synchronous and asynchronous output comparison

Synchronous output
The traditional log printing adopts the method of synchronous output. The so-called synchronous log means that when the log is output, the following business logic statements can be executed only after the log output statements are executed.
Use the logback synchronization log for log output. The log output statement and the program business logic statement will run in the same thread. In high concurrency scenarios, the number of logs not only surges, but as a disk IO, it is easy to create bottlenecks, resulting in thread jamming in the process of generating logs, which will affect the subsequent main business of the program and reduce the performance of the program.
Asynchronous output
When asynchronous logs are used for output, the log output statements and business logic statements are not run in the same thread, but there are special threads for log output operations. The main thread processing business logic can execute subsequent business logic without waiting. In this way, even if the log is not output, the main business of the program will not be affected, thus improving the performance of the program.

4, Asynchronous log implementation principle AsyncAppender

logback asynchronously outputs logs through AsyncAppender. AsyncAppender can record ILoggingEvents log events asynchronously.
However, it should be noted here that AsyncAppender only acts as an event allocator, and it must reference another Appender to complete the final log output.

Sketch Map:

The asynchronous output of Logback adopts the mode of producer and consumer, puts the generated logs into the message queue, and creates a thread to output log events, which effectively solves this problem and improves the performance of the program.
The asynchronous output log in logback uses AsyncAppender as an appender. By looking at the source code of AsyncAppender and its parent class AsyncAppenderBase, you can see that it has several important member variables:

AppenderAttachableImpl<E> aai = new AppenderAttachableImpl<E>();
BlockingQueue<E> blockingQueue;
AsyncAppenderBase<E>.Worker worker = new AsyncAppenderBase.Worker();

lockingQueue is a queue, and Worker is a consumption thread. It can basically be determined that it is a producer consumer mode.
Let's look at the main codes of the consumer (work):

while (parent.isStarted()) {
    try {
        E e = parent.blockingQueue.take();    //Single loop
        aai.appendLoopOnAppenders(e);
    } catch (InterruptedException ie) {
        break;
    }
}

A single while loop is used, that is, logback asynchronous output is written to the log file by a single consumer loop. The workflow is as follows:

5, Asynchronous log configuration

Configuration example:
The way to configure asynchronous log output is very simple. Add an appender based on asynchronous log writing and point to the originally configured appender.

<configuration>
	  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
	    <file>myapp.log</file>
	    <encoder>
	      <pattern>%logger{35} - %msg%n</pattern>
	    </encoder>
	  </appender>

	  <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
	     <appender-ref ref="FILE" />
         <!-- Set the size of the asynchronous blocking queue. In order not to lose logs, it is recommended to set it larger. 100000 is OK during the single machine pressure test. You should not worry about it OOM -->
        <queueSize>10000</queueSize>
        <!-- Set discard DEBUG,TRACE,INFO Log threshold value, not lost -->
        <discardingThreshold>0</discardingThreshold>
        <!-- Set the queue to be non blocking when entering the queue. When the queue is full, the logs will be directly discarded, but the performance will be greatly improved -->
        <neverBlock>true</neverBlock>
	  </appender>

	  <root level="DEBUG">
	    <appender-ref ref="ASYNC" />
	  </root>
 </configuration>

Description of core configuration parameters:

Attribute name	type	describe
queueSize	int	The maximum capacity of the BlockingQueue. By default, the size is 256.
discardingThreshold	int	Set the log discarding threshold. By default, when the queue has 20% capacity, it will discard the trace, debug and info logs, and only keep the warn and error logs.
includeCallerData	boolean	Extracting caller data can be quite expensive. To improve performance, by default, when an event is added to the event queue, the caller data associated with the event is not extracted. By default, only "cheap" data such as thread name and MDC are copied. By setting the includeecallerdata property to true, you can indicate that this add-on contains caller data.
maxFlushTime	int	Depending on the queue depth and latency of the referenced appender, AsyncAppender may take unacceptable time to completely refresh the queue. When the LoggerContext stops, the AsyncAppender stop method waits for the worker thread to complete until it times out. Use maxFlushTime to specify the maximum queue refresh timeout in milliseconds. Events that cannot be processed within this window will be discarded. The semantics of this value is the same as thread The semantics of join (long) are the same.
neverBlock	boolean	The default value is false, which indicates whether the thread is stuck when the queue is full. That is, if neverBlock=true is configured, when the queue is full, the messages that the later blocked threads want to output will be directly discarded, so that the threads will not block.

By default, the maximum capacity of event queue configuration is 256 events. If the queue is full, the application thread will be blocked from logging new events until the worker thread has a chance to dispatch one or more events. When the queue no longer reaches its maximum capacity, the application thread can start logging events again. Therefore, when an application runs at or near the capacity of its event buffer, asynchronous logging becomes pseudo synchronous. This is not necessarily a bad thing. The AsyncAppender asynchronous appender is designed to allow the application to continue running, although it takes a little more time to log events until the pressure on the attached buffer is reduced.

Optimizing the size of the appenders event queue for maximum application throughput depends on several factors.

Any or all of the following factors can cause pseudo synchronization behavior:

Large number of application threads
Each application call has a large number of log events
Each log event has a large amount of data
High latency of child appenders

To keep things going, it usually helps to increase the size of the queue at the cost of reducing the heap available to the application.

In order to reduce congestion, by default, when the queue capacity is reserved less than 20%, AsyncAppender will lose TRACE, DEBUG and INFO level events, and only keep WARN and ERROR level events. This strategy ensures non blocking processing of log events (and therefore excellent performance), while reducing TRACE, DEBUG, and INFO level events when the queue capacity is less than 20%. Event loss can be prevented by setting the discard threshold property to 0 (zero).

6, Performance test

In this part, I haven't had time to do tests. I quote some test data from the Internet.

Since the performance can be improved, a test comparison must be conducted. How many times can the synchronous and asynchronous output log performance be improved?

Server hardware

CPU six cores
Memory 8G

test tools

Apache Jmeter

1. Synchronous output log

Number of threads: 100
Ramp up loop (can be understood as the time taken to start threads):0 can be understood as 100 threads are enabled at the same time
Test results:

Focus on the indicator Throughput [TPS]: the number of requests processed by the system in a unit time. In the synchronous output log, the TPS is 44.2/sec