書接上回哀卫，在優(yōu)化完了httpClient線程池之后尸变，我們繼續(xù)增加吞吐量對(duì)該接口進(jìn)行施壓，看看是否仍有優(yōu)化的空間。同樣還是獲取ServiceB的堆棧日志并丟到gceasy(fastThread)中分析拄显，有了一個(gè)驚人的發(fā)現(xiàn)，竟然有一個(gè)線程阻塞了其他61個(gè)線程案站！
點(diǎn)開罪魁禍?zhǔn)?em>http-nio-8080-exec-86線程的堆棧信息躬审，看看它到底干了什么傷天害理之事搞得其他61個(gè)同僚只能擱那兒干瞪眼：
http-nio-8080-exec-86
Stack Trace is:
java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:326)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
- locked <0x00000006c0bbef40> (a java.io.BufferedOutputStream)
at ch.qos.logback.core.recovery.ResilientOutputStreamBase.flush(ResilientOutputStreamBase.java:79)
at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:133)
at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:187)
at ch.qos.logback.core.FileAppender.writeOut(FileAppender.java:279)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:212)
at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:414)
at ch.qos.logback.classic.Logger.info(Logger.java:587)
at com.sawyer.mall.service.impl.CommodityServiceImp.queryStock(CommodityServiceImp.java:225)
...
中略
...
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
- <0x00000006c0bc1db8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
- <0x00000006c6564120> (a java.util.concurrent.ThreadPoolExecutor$Worker)
通過分析堆棧信息可以看出，這個(gè)線程正在使用logback打印日志蟆盐，對(duì)照代碼里也只是很簡(jiǎn)單的一句：
log.info("業(yè)務(wù)日志");
在堆棧信息的最后承边，記錄了該線程持有的同步鎖信息Locked ownable synchronizers,可以看到該線程持有了一個(gè)很可疑的可重入鎖，鎖定對(duì)象為<0x00000006c0bc1db8>石挂，那其他線程一定是在等待這個(gè)對(duì)象的釋放博助，我們點(diǎn)開被阻塞的線程之一的http-nio-8080-exec-89：
http-nio-8080-exec-89
Stack Trace is:
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006c0bc1db8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210)
at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:398)
at ch.qos.logback.classic.Logger.info(Logger.java:583)
at com.sawyer.mall.commodity.impl.biz.CommodityBiz.queryByIdFromCache(CommodityBiz.java:253)
下略
...
發(fā)現(xiàn)里面有一句parking to wait for <0x00000006c0bc1db8>，表示該線程的確是因?yàn)榈却?code><0x00000006c0bc1db8>對(duì)象的釋放而被阻塞痹愚。那么為什么線程http-nio-8080-exec-86在寫日志的時(shí)候會(huì)持有一個(gè)可重入鎖呢富岳？難道logback寫入日志是同步寫入的嗎蛔糯？為了探究這個(gè)問題的答案，我們查看logback的源碼窖式，發(fā)現(xiàn)常規(guī)的appender（比如我們代碼里使用的RollingFileAppender）最終都會(huì)通過OutputStreamAppender類的append寫入日志：
/**
* All synchronization in this class is done via the lock object.
*/
protected final ReentrantLock lock = new ReentrantLock(false);
/**
* 中間代碼省略
*/
/**
* 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));
}
}
而這個(gè)方法里蚁飒，在真正寫入日志writeOut(event)前，使用了lock.lock()進(jìn)入了同步萝喘。這里大家可以思考下為什么這里要加鎖淮逻。
其實(shí)答案很簡(jiǎn)單，就是為了防止多線程的情況下阁簸，使用同一個(gè)appender的線程互相影響爬早，比如：
- 線程1寫了一半，線程2就把OutputStream關(guān)閉了强窖；
- 多個(gè)線程同時(shí)寫入導(dǎo)致日志內(nèi)容錯(cuò)亂凸椿。
那怎么才能優(yōu)化多線程高并發(fā)的場(chǎng)景，使logback不至于成為瓶頸呢翅溺？畢竟它畢竟只是個(gè)寫日志的工具脑漫，如果因?yàn)樗拗屏送掏铝浚瑢?shí)在是撿了芝麻丟了西瓜咙崎。
通過查看源碼和官方文檔發(fā)現(xiàn)优幸，除了常規(guī)的UnsynchronizedAppender外，還有一個(gè)異步的AsyncAppender褪猛，官方文檔對(duì)它的介紹如下：
AsyncAppender buffers events in a BlockingQueue. A worker thread created by
AsyncAppendertakes events from the head of the queue, and dispatches them to the single appender attached toAsyncAppender. Note that by default,AsyncAppenderwill drop events of level TRACE, DEBUG and INFO if its queue is 80% full. This strategy has an amazingly favorable effect on performance at the cost of event loss.
簡(jiǎn)而言之网杆，就是這個(gè)AsyncAppender創(chuàng)建了一個(gè)阻塞隊(duì)列，當(dāng)有日志需要寫入的時(shí)候伊滋，先放到這個(gè)隊(duì)列中碳却，并通過一個(gè)工作線程不停地將隊(duì)列中的日志寫入事件取出來執(zhí)行涂滴，其中很重要的一點(diǎn)是捂龄，這個(gè)隊(duì)列本身是有長度限制的纵东，一旦到達(dá)了80%的水位線肮疗，則TRACE, DEBUG和INFO級(jí)別的日志會(huì)被拋棄，最后官方還評(píng)價(jià)了一句尽狠，這個(gè)策略在損失一部分日志的代價(jià)下拿穴，會(huì)有顯著的性能提升蜕提。
閑話少敘我們還是來看關(guān)鍵源碼：
@Override
public void start() {
if (isStarted())
return;
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-" + getName());
// make sure this instance is marked as "started" before staring the worker Thread
super.start();
worker.start();
}
@Override
protected void append(E eventObject) {
//當(dāng)超過水位線且符合TRACE/DEBUG/INFO時(shí)乌妙，直接return使兔，不打日志
if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) {
return;
}
preprocess(eventObject);
put(eventObject);
}
private boolean isQueueBelowDiscardingThreshold() {
return (blockingQueue.remainingCapacity() < discardingThreshold);
}
private void put(E eventObject) {
if (neverBlock) {
blockingQueue.offer(eventObject);
} else {
try {
blockingQueue.put(eventObject);
} catch (InterruptedException e) {
// Interruption of current thread when in doAppend method should not be consumed
// by AsyncAppender
Thread.currentThread().interrupt();
}
}
}
work線程如下：
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);
parent.blockingQueue.remove(e);
}
aai.detachAndStopAllAppenders();
}
}
其實(shí)說白了，這就是跟我們用MQ同步轉(zhuǎn)異步一個(gè)道理藤韵，把本來同步寫入的日志先放到隊(duì)列里虐沥，然后一個(gè)個(gè)消費(fèi)。
要配置也很簡(jiǎn)單泽艘，在logback.xml中置蜀，將需要異步寫入的appender和AsyncAppender關(guān)聯(lián)即可：
<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
<discardingThreshold>0</discardingThreshold>
<queueSize>500</queueSize>
<neverBlock>true</neverBlock>
<appender-ref ref="bizAppender"/>
</appender>
<root>
<level value="INFO"/>
<appender-ref ref="ASYNC"/>
...
</root>
這里有三個(gè)重要的參數(shù)：
-
discardingThreshold用來指定拋棄的水位線奈搜，默認(rèn)80%悉盆； -
queueSize用來指定隊(duì)列大小盯荤，默認(rèn)256； -
neverBlock用來指定當(dāng)隊(duì)列已滿時(shí)放入新的日志事件是否拋出異常焕盟，查看上面put方法即可發(fā)現(xiàn)秋秤，如果為true則使用offer，否則使用put脚翘，區(qū)別為前者非阻塞后者阻塞灼卢。
