碼上快樂

相關內容    簡體    繁體

logback最佳實踐

本文轉載自   查看原文   2020-07-17 16:53   501 

背景

在最近的一次項目性能優化過程中，通過火焰圖工具發現logback占用CPU很多，因此有了這篇總結文章。

logback 同步 vs 異步

同步寫日志一般配置如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
 
 <appender name="ORDER_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
 <file>/data/logs/AAA/order.log</file>
 <encoder>
 <pattern>[%-5p] [%d{yyyy-MM-dd HH:mm:ss.SSS}] [%X{tracing_id}] [%C{1}:%M:%L] %m%n</pattern>
 <immediateFlush>false</immediateFlush> 
 </encoder>
 <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
 <level>INFO</level>
 </filter>
 <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
 <fileNamePattern>/data/logs/AAA/order.log.%d{yyyy-MM-dd_HH}</fileNamePattern>
 </rollingPolicy>
</appender>

從配置可以看出來，寫日志到日志文件的操作由RollingFileAppender完成，該類的繼承結構如下：

undefined

從繼承結構可以知道RollingFileAppender繼承了UnsynchronizedAppenderBase，根據doc文檔說明，RollingFileAppender需要自己處理多線程同步的問題。 在內部它確實也自己做了同步。

RollingFileAppender

1
2
3
4
5
6
7
8
9
10
11
12
13
14
 
@Override
protected void subAppend(E event) {
 // The roll-over check must precede actual writing. This is the
 // only correct behavior for time driven triggers.

 // We need to synchronize on triggeringPolicy so that only one rollover
 // occurs at a time
 synchronized (triggeringPolicy) {
 if (triggeringPolicy.isTriggeringEvent(currentlyActiveFile, event)) {
 rollover();
 }
 }
 super.subAppend(event);
}

OutputStreamAppender.java

OutputStreamAppender.java

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
 
/**
* All synchronization in this class is done via the lock object.
*/
protected LogbackLock lock = new LogbackLock();
 
protected void subAppend(E event) {
 if (!isStarted()) {
 return;
 }
 try {
 // this step avoids LBCLASSIC-139
 if (event instanceof DeferredProcessingAware) {
 ((DeferredProcessingAware) event).prepareForDeferredProcessing();
 }
 // the synchronization prevents the OutputStream from being closed while we
 // are writing. It also prevents multiple threads from entering the same
 // converter. Converters assume that they are in a synchronized block.
 synchronized (lock) {
 writeOut(event);
 }
 } catch (IOException ioe) {
 // as soon as an exception occurs, move to non-started state
 // and add a single ErrorStatus to the SM.
 this.started = false;
 addStatus(new ErrorStatus("IO failure in appender", this, ioe));
 }
}
// 通過 encode進行日志序列化，格式化寫入
protected void writeOut(E event) throws IOException {
 this.encoder.doEncode(event);
}

LayoutWrappingEncoder.java

1
2
3
4
5
6
7
8
9
10
 
LayoutWrappingEncoder.java
private boolean immediateFlush = true;
public void doEncode(E event) throws IOException {
 String txt = layout.doLayout(event);
 outputStream.write(convertToBytes(txt));
 //是否立即寫入
 if (immediateFlush)
 outputStream.flush();
 }
}

通過上面的代碼邏輯可以得出如下結論：

  1. RollingFileAppender 寫日志自己實現了多線程同步。
  2. RollingFileAppender 寫日志是直接接入到日志文件中的。
  3. RollingFileAppender 默認日志到文件后會立刻flush，保證日志不丟失。
  4. 因為是順序寫文件，速度還是很高的，但是應為每次都flush，這會影響性能。

為了防止寫日志影響應用性能， 我們需要使用異步寫日志的方式。

異步寫日志一般配置如下：

1
2
3
4
5
6
7
8
9
10
 
<appender name ="ASYNC_ORDER_LOG" class= "ch.qos.logback.classic.AsyncAppender">
 // 不丟棄日志
 <discardingThreshold>0</discardingThreshold>
 <queueSize>512</queueSize>
 <includeCallerData>true</includeCallerData>
 // 如果設置為true，隊列滿了會直接丟棄信息，而不是阻塞（其實就是使用的offer而不是put方法）
 <neverBlock>false</neverBlock>
 // 指定底層真實使用的Appender
 <appender-ref ref ="ORDER_LOG"/>
</appender>

undefined

AsyncAppender 繼承自 AsyncAppenderBase。 AsyncAppenderBase的doc文檔有如下的描述：

AsyncAppenderBase的子類寫日志是異步的方式，內部使用了 BlockingQueue（異步寫日志就是一個生產者-消費者模式）。
BlockingQueue 的使用者負責在應用關閉時關閉BlockingQueue，來確保不丟失日志。

注意：不丟失日志，可以通過如下的方式實現:

1
2
3
 
<configuration debug="true">
 <shutdownHook class="ch.qos.logback.core.hook.DelayingShutdownHook" />
</configuration>

或

1
2
3
4
 
Runtime.addShutdownHook(new Thread (() -> {
 LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
 loggerContext.stop();
}));

AsyncAppenderBase代碼分析:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
 
public static final int DEFAULT_QUEUE_SIZE = 256;
// 默認阻塞隊列大小
int queueSize = DEFAULT_QUEUE_SIZE;
static final int UNDEFINED = -1;
// 初始值為 -1， 在啟動時默認值是通過queueSize的大小計算出來的。
int discardingThreshold = UNDEFINED;

// 異步寫日志的線程
Worker worker = new Worker();

@Override
public void start() {
 if (appenderCount == 0) {
 addError("No attached appenders found.");
 return;
 }
 if (queueSize < 1) {
 addError("Invalid queue size [" + queueSize + "]");
 return;
 }
 blockingQueue = new ArrayBlockingQueue<E>(queueSize);

 if (discardingThreshold == UNDEFINED)
 discardingThreshold = queueSize / 5;
 addInfo("Setting discardingThreshold to " + discardingThreshold);
 worker.setDaemon(true);
 worker.setName("AsyncAppender-Worker-" + worker.getName());
 // make sure this instance is marked as "started" before staring the worker Thread
 super.start();
 worker.start();
}
 
@Override
protected void append(E eventObject) {
 // 可以的隊列容量小於配置的值 並且 日志事件的級別為INFO及一下，那么就丟棄日志。
 if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) {
 return;
 }
 preprocess(eventObject);
 put(eventObject);
}

private boolean isQueueBelowDiscardingThreshold() {
 return (blockingQueue.remainingCapacity() < discardingThreshold);
}

protected boolean isDiscardable(ILoggingEvent event) {
 Level level = event.getLevel();
 return level.toInt() <= Level.INFO_INT;
}

protected void preprocess(ILoggingEvent eventObject) {
 eventObject.prepareForDeferredProcessing();
 // 是否需要獲取調用者信息，這也是一個耗時操作，默認是false（內部通過創建異常對象，獲取堆棧信息，從而計算日志發送的類，方法，行號信息）。
 if(includeCallerData)
 eventObject.getCallerData();
}

private void put(E eventObject) {
 try {
 // 阻塞操作
 blockingQueue.put(eventObject);
 } catch (InterruptedException e) {
 }
}

class Worker extends Thread {

 public void run() {
 AsyncAppenderBase<E> parent = AsyncAppenderBase.this;
 AppenderAttachableImpl<E> aai = parent.aai;

 // loop while the parent is started
 while (parent.isStarted()) {
 try {
 // 從隊列中獲取數據，其實就是消費者
 E e = parent.blockingQueue.take();
 aai.appendLoopOnAppenders(e);
 } catch (InterruptedException ie) {
 break;
 }
 }

 addInfo("Worker thread will flush remaining events before exiting. ");
 for (E e : parent.blockingQueue) {
 aai.appendLoopOnAppenders(e);
 }

 aai.detachAndStopAllAppenders();
 }
}

小結

  1. 同步寫日志而且immediateFlush=true的配置下，性能最差。原因是寫磁盤導致其他線程等待時間過長，雖然是順序寫，但是畢竟是持久化數據到磁盤。當然了，SSD能好一點。
  2. 異步寫在JVM突然crash的時候有丟失數據的風險，但是性能很高，原因在於避免了直接寫磁盤帶來的性能消耗。但是需要注意的是多線程操作同一個阻塞隊列也會因為鎖爭用的問題影響性能。
    a. 不同的模塊配置不同的日志文件和Appender，能減少鎖爭用的問題。
    b. 減少不必要的日志輸出。
    c. 增加阻塞隊列的大小，在neverBlock=false的情況下避免線程等待問題。
    d. 多個Appender（SiftingAppender），底層還是寫同一個文件。好處是減少了多線程在阻塞隊列上的鎖競爭問題。

SiftingAppender

SiftingAppender是logback根據mdc中的變量動態創建appender的代理，只要我們將一個線程號作為日志名分發器discriminator注入到SiftingAppender中，它就可以動態的為我們創建不同的appender，達到分線程的目的，配置方式舉例如下：

<!-- 分線程輸出源 --> <appender name="frameworkthread" class="ch.qos.logback.classic.sift.SiftingAppender"> <discriminator class="ThreadDiscriminator"> <key>threadName</key> </discriminator> <sift> <appender name="FILE-${threadName}" class="ch.qos.logback.core.rolling.RollingFileAppender"> <encoder> <Encoding>UTF-8</Encoding> <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS}[%c][%thread][%X{tradeNo}][%p]-%m%n</pattern> </encoder> <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"> <fileNamePattern>D:/test/threadlogs/${threadName}-%d{yyyy-MM-dd}.%i.log </fileNamePattern> <maxFileSize>100MB</maxFileSize> <maxHistory>60</maxHistory> <totalSizeCap>20GB</totalSizeCap> </rollingPolicy> </appender> </sift> </appender>

參考資料

http://logback.qos.ch/manual/appenders.html
一次logback多線程調優的經歷

 

原文鏈接：https://leokongwq.github.io/2019/12/14/logback-best-practise.html


免責聲明！

本站轉載的文章為個人學習借鑒使用，本站對版權不負任何法律責任。如果侵犯了您的隱私權益，請聯系本站郵箱yoyou2525@163.com刪除。



猜您在找 Spring Boot之logback日志最佳實踐 55最佳實踐系列：Logging最佳實踐 55最佳實踐系列：MongoDB最佳實踐 mapstruct最佳實踐 Django與Celery最佳實踐 memcached的最佳實踐方案 jQuery最佳實踐 AKS (1) AKS最佳實踐 深入Vuex最佳實踐 Kafka最佳實踐
 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM