Due to the impact of Typhoon Lekima, many places have received heavy rainfall, so you can’t go out to play on weekends. Let’s learn together. Let’s start with the basic configuration and then introduce advanced features asynchronous log output. Scroll down a bit if you only want to see how asynchronous logging improves performance.

You will find out by reading this article

  • 1. Output logs to files based onLEVELLevel Logs are classified and saved to different files
  • 2. Reduce the number of disks by sending logs asynchronouslyIOTo improve performance
  • 3. Mechanism of asynchronous log output

Configuration file logback-spring.xml

The SpringBoot project comes with logback and SLF4J dependencies, so the focus is on writing configuration files, and what dependencies need to be introduced, and log dependency conflicts are completely irrelevant. The Logback framework loads a configuration file named logback-spring or logback in the classpath by default. Store all logs in one file. The file size grows with the running of the application and it is difficult to troubleshoot problems. The correct method is to separate error logs from other logs and store logs of different levels according to the time period.

<? xml version="1.0" encoding="utf-8"? > <configuration> <property resource="logback.properties"/>
    <appender name="CONSOLE-LOG" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <pattern>[%d{yyyy-MM-dd' 'HH:mm:ss.sss}] [%C] [%t] [%L] [%-5p] %m%n</pattern> </layout> </appender> <! <appender name= -- get logs with levels higher than info (including info) but not error"INFO-LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>DENY</onMatch>
            <onMismatch>ACCEPT</onMismatch>
        </filter>
        <encoder>
            <pattern>[%d{yyyy-MM-dd' 'HH:mm:ss.sss}] [%C] [%t] [%L] [%-5p] %m%n</pattern> </encoder> <! --> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <! -- Path --> <fileNamePattern>${LOG_INFO_HOME}//%d.log</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
    </appender>
    <appender name="ERROR-LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>ERROR</level>
        </filter>
        <encoder>
            <pattern>[%d{yyyy-MM-dd' 'HH:mm:ss.sss}] [%C] [%t] [%L] [%-5p] %m%n</pattern> </encoder> <! --> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <! -- Path --> <fileNamePattern>${LOG_ERROR_HOME}//%d.log</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
    </appender>

    <root level="info">
        <appender-ref ref="CONSOLE-LOG" />
        <appender-ref ref="INFO-LOG" />
        <appender-ref ref="ERROR-LOG" />
    </root>
</configuration>

Copy the code

Partial Label Description

  • <root>Tag, a mandatory tag that specifies the most basic log output level
    • <appender-ref>Tag, addappend
  • <append>Tag that specifies the collection policy for logs
    • nameAttribute specifiesappendernamed
    • classProperty specifies the output strategy. There are usually two types, console output and file output, which is to persist the log.ConsoleAppenderOutput logs to the console
  • <filter>Tag that you can use to specify a filtering policy
    • <level>The tag specifies the type of filtering
  • <encoder>Tag, using the tag under<pattern>The tag specifies the log output format
  • <rollingPolicy>The tag specifies a collection policy, such as time-based collection
    • <fileNamePattern>This configuration has achieved the goal of dividing mobile phone logs by day

Logback Advanced features Asynchronously output logs

The previous log configuration is based on synchronization. Disk I/O is performed every time logs are output to a file. Asynchronous log writing prevents disk I/OS that block threads and cause unnecessary performance loss. Writing logs asynchronously is as simple as adding an appender based on writing logs asynchronously and pointing to the configured appender

<! -- asynchronous output --> <appender name="ASYNC-INFO" class="ch.qos.logback.classic.AsyncAppender"> <! -- Do not lose logs. The system discards cards with 80% of the queue being full. For example, TRACT, DEBUG, and INFO logs are discarded. <discardingThreshold>0</discardingThreshold> Change the default queue depth, which affects performance. The default value is 256 --> <queueSize>256</queueSize> <! Appender-ref = appender-ref = appender-ref = appender-ref = appender-ref = appender-ref ="INFO-LOG"/>
    </appender>

    <appender name="ASYNC-ERROR" class="ch.qos.logback.classic.AsyncAppender"> <! -- Do not lose logs. The system discards cards with 80% of the queue being full. For example, TRACT, DEBUG, and INFO logs are discarded. <discardingThreshold>0</discardingThreshold> Change the default queue depth, which affects performance. The default value is 256 --> <queueSize>256</queueSize> <! Appender-ref = appender-ref = appender-ref = appender-ref = appender-ref = appender-ref ="ERROR-LOG"/>
    </appender>
Copy the code

Asynchronous output log performance test

If you can improve performance, you must do a test comparison. How many times can synchronous and asynchronous log output improve performance?

Server hardware
  • CPUSix nuclear
  • 8 g memory
Testing tools

Apache Jmeter

Synchronizing Output Logs
  • Number of threads: 100
  • Ramp-Up Loop0 can be interpreted as 100 threads enabled at the same time
  • The test results

    Focus on indicatorsThroughput (TPS)Throughput: The number of requests processed per unit of time by the system, in synchronous output logsTPSfor44.2 / SEC

Asynchronously Outputting Logs
  • The number of threads, 100
  • Ramp-Up Loop: 0
  • The test results

    TPSfor497.5 / SEC.Performance increased by more than 10 times!!

Mechanism of asynchronous log output

Start tracing from the logger. info method in the Logback framework. The method call path is shown below:

ch.qos.logback.classic
AsyncAppenderBase
append 

protected void append(E eventObject) {
        if(! this.isQueueBelowDiscardingThreshold() || ! this.isDiscardable(eventObject)) { this.preprocess(eventObject); this.put(eventObject); }}Copy the code

If not, put it on a blocking queue. By looking at the code, this blocking queue is ArrayBlockingQueueu, with a default size of 256, which can be modified through the configuration file. Logger.info(…) To append (…). It’s done, just stuff the log into the blocking queue, and continue logger.info (…) The following statement. The AsyncAppenderBase class defines a Worker thread. The key parts of the run method are as follows:

E e = parent.blockingQueue.take();
aai.appendLoopOnAppenders(e);
Copy the code

Pull a log from the blocking queue and maintain a list of Appends by calling the appendLoopOnAppenders method of the AppenderAttachableImpl class. The process of calling methods in Worker thread is mainly shown as follows:

encode
write
encode




Complete project code

= = = = = = = = = = = = = = = = = = = = = = Update On 2019/09/02 = = = = = = = = = = = = = = = = = = = = test results in fewer pollution, repetition, less sample size problem, After the retest, the TPS difference between synchronous and asynchronous logback logs was not significant. Attached is the performance test report. But there is still a reduction in time