logback非同步輸出日誌的配置方法和原始碼分析
阿新 • • 發佈：2019-01-01
1，非同步輸出日誌的配置
logback中的非同步輸出日誌使用了AsyncAppender這個appender
配置方式如下：
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <fileNamePattern>logs/context-log.%d{yyyy-MM-dd}.log</fileNamePattern> <maxHistory>30</maxHistory> </rollingPolicy> <encoder charset="UTF-8"> <pattern>[%-5level] %date --%thread-- [%logger] %msg %n</pattern> </encoder> </appender> <appender name ="ASYNC_FILE" class= "ch.qos.logback.classic.AsyncAppender"> <discardingThreshold >0</discardingThreshold> <queueSize>1234</queueSize> <appender-ref ref = "FILE"/> </appender>
AsyncAppender的父類是AsyncAppenderBase，用到的程式碼基本都在這個父類裡面。
2，非同步輸出日誌時會把資訊放到BlockingQueue中
當執行logger.info()方法時，Logger裡的原始碼是這樣的：
Logger類：ch.qos.logback.classic.Logger
info方法：
public void info(String msg) {
filterAndLog_0_Or3Plus(FQCN, null, Level.INFO, msg, null, null);
}中間判斷了一下日誌級別，如果本日誌級別比配置的級別低，就不打日誌了。比如配置的日誌級別是ERROR，但是這段程式碼的級別是INFO，這段日誌就不列印了。private void filterAndLog_0_Or3Plus(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params, final Throwable t) { final FilterReply decision = loggerContext .getTurboFilterChainDecision_0_3OrMore(marker, this, level, msg, params, t); if (decision == FilterReply.NEUTRAL) { if (effectiveLevelInt > level.levelInt) { return; } } else if (decision == FilterReply.DENY) { return; } buildLoggingEventAndAppend(localFQCN, marker, level, msg, params, t); }
最後的buildLoggingEventAndAppend方法：
在這一步封裝了LoggingEvent物件，Logback後面對日誌的處理基本都是以LoggingEvent物件為單位了。private void buildLoggingEventAndAppend(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params, final Throwable t) { LoggingEvent le = new LoggingEvent(localFQCN, this, level, msg, t, params); le.setMarker(marker); callAppenders(le); }
最後的callAppenders方法的程式碼：
/**
* Invoke all the appenders of this logger.
*
* @param event
* The event to log
*/
public void callAppenders(ILoggingEvent event) {
int writes = 0;
for (Logger l = this; l != null; l = l.parent) {
writes += l.appendLoopOnAppenders(event);
if (!l.additive) {
break;
}
}
// No appenders in hierarchy
if (writes == 0) {
loggerContext.noAppenderDefinedWarning(this);
}
}appendLoopOnAppenders方法：
private int appendLoopOnAppenders(ILoggingEvent event) {
if (aai != null) {
return aai.appendLoopOnAppenders(event);
} else {
return 0;
}
}Logger相關的appender就是配置檔案中的ch.qos.logback.classic.AsyncAppender類，另外配置檔案中的ch.qos.logback.core.rolling.RollingFileAppender不算，他屬於AsyncAppender，不屬於Logger。
AppenderAttachableImpl類的appendLoopOnAppenders方法：
/**
* Call the <code>doAppend</code> method on all attached appenders.
*/
public int appendLoopOnAppenders(E e) {
int size = 0;
for (Appender<E> appender : appenderList) {
appender.doAppend(e);
size++;
}
return size;
}AsyncAppender的父類是AsyncAppenderBase，在ch.qos.logback.core包下
AsyncAppenderBase的父類是UnsynchronizedAppenderBase，也在ch.qos.logback.core包下，doAppend方法在這個類中：
public void doAppend(E eventObject) {
// WARNING: The guard check MUST be the first statement in the
// doAppend() method.
// prevent re-entry.
if (Boolean.TRUE.equals(guard.get())) {
return;
}
try {
guard.set(Boolean.TRUE);
if (!this.started) {
if (statusRepeatCount++ < ALLOWED_REPEATS) {
addStatus(new WarnStatus(
"Attempted to append to non started appender [" + name + "].",
this));
}
return;
}
if (getFilterChainDecision(eventObject) == FilterReply.DENY) {
return;
}
// ok, we now invoke derived class' implementation of append
this.append(eventObject);
} catch (Exception e) {
if (exceptionCount++ < ALLOWED_REPEATS) {
addError("Appender [" + name + "] failed to append.", e);
}
} finally {
guard.set(Boolean.FALSE);
}
}@Override
protected void append(E eventObject) {
if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) {
return;
}
preprocess(eventObject);
put(eventObject);
}
然後append方法裡的put方法：
private void put(E eventObject) {
try {
blockingQueue.put(eventObject);
} catch (InterruptedException e) {
}
}日誌的內容會被放到AsyncAppenderBase裡定義的一個BlockingQueue中，至此Logger.info的任務完成了。
所謂的非同步輸出日誌就是Logger.info負責往Queue中放日誌，再起個執行緒把Queue中的日誌寫到磁碟上。
3，從BlockingQueue中獲取資訊並寫入到檔案
在AsyncAppender的父類AsyncAppenderBase裡面定義了一個叫Worker的內部類，這個類負責從BlockingQueue中取出資訊並處理，Worker的定義如下：
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();
}
}
另外AsyncAppenderBase還定義了Worker執行緒的start和stop方法，是重寫的父類UnsynchronizedAppenderBase中的方法：
@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
public void stop() {
if (!isStarted())
return;
// mark this appender as stopped so that Worker can also processPriorToRemoval if it is invoking aii.appendLoopOnAppenders
// and sub-appenders consume the interruption
super.stop();
// interrupt the worker thread so that it can terminate. Note that the interruption can be consumed
// by sub-appenders
worker.interrupt();
try {
worker.join(1000);
} catch (InterruptedException e) {
addError("Failed to join worker thread", e);
}
}
可以看到，在while迴圈期間，Worker從blockingQueue裡面拿出一個元素並進行處理，還是呼叫了AppenderAttachableImpl的appendLoopOnAppenders方法（和上面一樣）：
/**
* Call the <code>doAppend</code> method on all attached appenders.
*/
public int appendLoopOnAppenders(E e) {
int size = 0;
for (Appender<E> appender : appenderList) {
appender.doAppend(e);
size++;
}
return size;
}
呼叫了所有Appender的doAppend方法，在上面的配置中，AsyncAppenderBase相關的appender是RollingFileAppender，在ch.qos.logback.core.rolling包中
RollingFileAppender的父類是FileAppender，在ch.qos.logback.core包中
FileAppender的父類是OutputStreamAppender，也在ch.qos.logback.core包中
OutputStreamAppender的父類是UnsynchronizedAppenderBase，doAppend方法在這個類中（還是和上面的一樣）：
public void doAppend(E eventObject) {
// WARNING: The guard check MUST be the first statement in the
// doAppend() method.
// prevent re-entry.
if (Boolean.TRUE.equals(guard.get())) {
return;
}
try {
guard.set(Boolean.TRUE);
if (!this.started) {
if (statusRepeatCount++ < ALLOWED_REPEATS) {
addStatus(new WarnStatus(
"Attempted to append to non started appender [" + name + "].",
this));
}
return;
}
if (getFilterChainDecision(eventObject) == FilterReply.DENY) {
return;
}
// ok, we now invoke derived class' implementation of append
this.append(eventObject);
} catch (Exception e) {
if (exceptionCount++ < ALLOWED_REPEATS) {
addError("Appender [" + name + "] failed to append.", e);
}
} finally {
guard.set(Boolean.FALSE);
}
}
這段程式碼，經過了一堆的判斷和設定，呼叫了append方法，自己類裡的append方法是個抽象方法，具體的實現寫在了他的子類OutputStreamAppender裡，程式碼如下：
@Override
protected void append(E eventObject) {
if (!isStarted()) {
return;
}
subAppend(eventObject);
}
然後是subAppend方法：
/**
* Actual writing occurs here.
* <p>
* Most subclasses of <code>WriterAppender</code> will need to override this
* method.
*
* @since 0.9.0
*/
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.
lock.lock();
try {
writeOut(event);
} finally {
lock.unlock();
}
} 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));
}
}
然後是writeOut方法：
protected void writeOut(E event) throws IOException {
this.encoder.doEncode(event);
}
呼叫了encoder的doEncode方法，encoder的類是Encoder，Encoder是OutputStreamAppender定義的最終負責寫日誌的介面，由LayoutWrappingEncoder類實現：
public void setLayout(Layout<E> layout) {
addWarn("This appender no longer admits a layout as a sub-component, set an encoder instead.");
addWarn("To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.");
addWarn("See also "+CODES_URL+"#layoutInsteadOfEncoder for details");
LayoutWrappingEncoder<E> lwe = new LayoutWrappingEncoder<E>();
lwe.setLayout(layout);
lwe.setContext(context);
this.encoder = lwe;
} public void doEncode(E event) throws IOException {
String txt = layout.doLayout(event);
outputStream.write(convertToBytes(txt));
if (immediateFlush)
outputStream.flush();
}用OutputStream寫日誌，immediateFlush可以在配置檔案裡配置，代表是否立即清空資訊流，預設為true，如果配置為false，則會讓outputStream快滿的時候清空資訊流。
至此日誌寫入完畢
4，一些可能有用的配置方式
1，blockingQueue長度。
blockingQueue長度決定了佇列能放多少資訊，在預設的配置下，如果blockingQueue放滿了，後續想要輸出日誌的執行緒會被阻塞，直到Worker執行緒處理掉佇列中的資訊為止。根據實際情況適當調整佇列長度，可以防止執行緒被阻塞。
2，immediateFlush=false。不立即清空輸出流。
immediateFlush引數可以配置在<appender>裡面，預設是true，代表是否立即重新整理OutputStream中的資訊。如果設定為false，會在OutputStream放滿或隔斷時間進行flush，具體由OutputStream類決定。據說設定為false之後輸出日誌的效率能提高為原來的4倍。
官網說：setting thisproperty to 'false' is likely to quadruple (your mileage may vary) loggingthroughput.
3，neverBlock=true。佇列滿了也不卡執行緒
neverBlock引數可以配置在<appender>裡面，預設是false，代表在佇列放滿的情況下是否卡住執行緒。也就是說，如果配置neverBlock=true，當佇列滿了之後，後面阻塞的執行緒想要輸出的訊息就直接被丟棄，從而執行緒不會阻塞。這個配置用於執行緒很重要，不能卡頓，而且日誌又不是很重要的場景，因為很有可能會丟日誌。
4，自定義appender
開發者可以自己寫一個appender類，需要繼承AppenderBase<LoggingEvent>類並重寫append(LoggingEventeventObject)方法，然後像別的appender一樣配置到logback.xml裡面，就可以定義自己的日誌輸出方式了。