書(shū)接上回，在優(yōu)化完了httpClient線(xiàn)程池之后，我們繼續(xù)增加吞吐量對(duì)該接口進(jìn)行施壓，看看是否仍有優(yōu)化的空間。同樣還是獲取ServiceB的堆棧日志并丟到gceasy(fastThread)中分析，有了一個(gè)驚人的發(fā)現(xiàn)，竟然有一個(gè)線(xiàn)程阻塞了其他61個(gè)線(xiàn)程！
點(diǎn)開(kāi)罪魁禍?zhǔn)?em>http-nio-8080-exec-86線(xiàn)程的堆棧信息，看看它到底干了什么傷天害理之事搞得其他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)
通過(guò)分析堆棧信息可以看出，這個(gè)線(xiàn)程正在使用logback打印日志，對(duì)照代碼里也只是很簡(jiǎn)單的一句：
log.info("業(yè)務(wù)日志");
在堆棧信息的最后，記錄了該線(xiàn)程持有的同步鎖信息Locked ownable synchronizers,可以看到該線(xiàn)程持有了一個(gè)很可疑的可重入鎖，鎖定對(duì)象為<0x00000006c0bc1db8>，那其他線(xiàn)程一定是在等待這個(gè)對(duì)象的釋放，我們點(diǎn)開(kāi)被阻塞的線(xià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>，表示該線(xiàn)程的確是因?yàn)榈却?code><0x00000006c0bc1db8>對(duì)象的釋放而被阻塞。那么為什么線(xiàn)程http-nio-8080-exec-86在寫(xiě)日志的時(shí)候會(huì)持有一個(gè)可重入鎖呢？難道logback寫(xiě)入日志是同步寫(xiě)入的嗎？為了探究這個(gè)問(wèn)題的答案，我們查看logback的源碼，發(fā)現(xiàn)常規(guī)的appender（比如我們代碼里使用的RollingFileAppender）最終都會(huì)通過(guò)OutputStreamAppender類(lèi)的append寫(xiě)入日志：
/**
* 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è)方法里，在真正寫(xiě)入日志writeOut(event)前，使用了lock.lock()進(jìn)入了同步。這里大家可以思考下為什么這里要加鎖。
其實(shí)答案很簡(jiǎn)單，就是為了防止多線(xiàn)程的情況下，使用同一個(gè)appender的線(xiàn)程互相影響，比如：
- 線(xiàn)程1寫(xiě)了一半，線(xiàn)程2就把OutputStream關(guān)閉了；
- 多個(gè)線(xiàn)程同時(shí)寫(xiě)入導(dǎo)致日志內(nèi)容錯(cuò)亂。
那怎么才能優(yōu)化多線(xiàn)程高并發(fā)的場(chǎng)景，使logback不至于成為瓶頸呢？畢竟它畢竟只是個(gè)寫(xiě)日志的工具，如果因?yàn)樗拗屏送掏铝浚瑢?shí)在是撿了芝麻丟了西瓜。
通過(guò)查看源碼和官方文檔發(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)有日志需要寫(xiě)入的時(shí)候，先放到這個(gè)隊(duì)列中，并通過(guò)一個(gè)工作線(xiàn)程不停地將隊(duì)列中的日志寫(xiě)入事件取出來(lái)執(zhí)行，其中很重要的一點(diǎn)是，這個(gè)隊(duì)列本身是有長(zhǎng)度限制的，一旦到達(dá)了80%的水位線(xiàn)，則TRACE, DEBUG和INFO級(jí)別的日志會(huì)被拋棄，最后官方還評(píng)價(jià)了一句，這個(gè)策略在損失一部分日志的代價(jià)下，會(huì)有顯著的性能提升。
閑話(huà)少敘我們還是來(lái)看關(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)超過(guò)水位線(xiàn)且符合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線(xiàn)程如下：
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í)說(shuō)白了，這就是跟我們用MQ同步轉(zhuǎn)異步一個(gè)道理，把本來(lái)同步寫(xiě)入的日志先放到隊(duì)列里，然后一個(gè)個(gè)消費(fèi)。
要配置也很簡(jiǎn)單，在logback.xml中，將需要異步寫(xiě)入的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用來(lái)指定拋棄的水位線(xiàn)，默認(rèn)80%； -
queueSize用來(lái)指定隊(duì)列大小，默認(rèn)256； -
neverBlock用來(lái)指定當(dāng)隊(duì)列已滿(mǎn)時(shí)放入新的日志事件是否拋出異常，查看上面put方法即可發(fā)現(xiàn)，如果為true則使用offer，否則使用put，區(qū)別為前者非阻塞后者阻塞。
