你完全沒了解過的日志異步落庫

前言

在互聯(lián)網(wǎng)設(shè)計(jì)架構(gòu)過程中，日志異步落庫，儼然已經(jīng)是高并發(fā)環(huán)節(jié)中不可缺少的一環(huán)。為什么說是高并發(fā)環(huán)節(jié)中不可缺少的呢？ 原因在于，如果直接用mq進(jìn)行日志落庫的時候，低并發(fā)下，生產(chǎn)端生產(chǎn)數(shù)據(jù)，然后由消費(fèi)端異步落庫，是沒有什么問題的，而且性能也都是異常的好，估計(jì)tp99應(yīng)該都在1ms以內(nèi)。但是一旦并發(fā)增長起來，慢慢的你就發(fā)現(xiàn)生產(chǎn)端的tp99一直在增長，從1ms，變?yōu)?ms，4ms，直至send timeout。尤其在大促的時候，我司的系統(tǒng)就經(jīng)歷過這個情況，當(dāng)時mq的發(fā)送耗時超過200ms，甚至一度有不少timeout產(chǎn)生。

考慮到這種情況在高并發(fā)的情況下才出現(xiàn)，所以今天我們就來探索更加可靠的方法來進(jìn)行異步日志落庫，保證所使用的方式不會因?yàn)檫^高的并發(fā)而出現(xiàn)接口ops持續(xù)下降甚至到不可用的情況。

方案一： 基于log4j的異步appender實(shí)現(xiàn)

此種方案，依賴于log4j。在log4j的異步appender中，通過mq進(jìn)行生產(chǎn)消費(fèi)入庫。相當(dāng)于在接口和mq之間建立了一個緩沖區(qū)，使得接口和mq的依賴分離，從而不讓mq的操作影響接口的ops。

此種方案由于使用了異步方式，且由于異步的discard policy策略，當(dāng)大量數(shù)據(jù)過來，緩沖區(qū)滿了之后，會拋棄部分?jǐn)?shù)據(jù)。此種方案適用于能夠容忍數(shù)據(jù)丟失的業(yè)務(wù)場景，不適用于對數(shù)據(jù)完整有嚴(yán)格要求的業(yè)務(wù)場景。

來看看具體的實(shí)現(xiàn)方式：

首先，我們需要自定義一個Appender，繼承自log4j的AppenderSkeleton類，實(shí)現(xiàn)方式如下：

public class AsyncJmqAppender extends AppenderSkeleton {
    @Resource(name = "messageProducer")
    private MessageProducer messageProducer;
    @Override    protected void append(LoggingEvent loggingEvent) {
        asyncPushMessage(loggingEvent.getMessage());
    }
    /**
     * 異步調(diào)用jmq輸出日志
     * @param message
     */    private void asyncPushMessage(Object message) {
        CompletableFuture.runAsync(() -> {
            Message messageConverted = (Message) message;
            try {
                messageProducer.send(messageConverted);
            } catch (JMQException e) {
                e.printStackTrace();
            }
        });
    }
    @Override    public boolean requiresLayout() {
        return false;
    }
    @Override    public void close() {
    }
}

然后在log4j.xml中，為此類進(jìn)行配置：

<!--異步JMQ appender--><appender name="async_mq_appender" class="com.jd.limitbuy.common.util.AsyncJmqAppender">    <!-- 設(shè)置File參數(shù)：日志輸出文件名 -->    <param name="File" value="D:/export/Instances/order/server1/logs/order.async.jmq" />    <!-- 設(shè)置是否在重新啟動服務(wù)時，在原有日志的基礎(chǔ)添加新日志 -->    <param name="Append" value="true" />    <!-- 設(shè)置文件大小 -->    <param name="MaxFileSize" value="10KB" />    <!-- 設(shè)置文件備份 -->    <param name="MaxBackupIndex" value="10000" />    <!-- 設(shè)置輸出文件項(xiàng)目和格式 -->    <layout class="org.apache.log4j.PatternLayout">        <param name="ConversionPattern" value="%m%n" />    </layout></appender><logger name="async_mq_appender_logger">    <appender-ref ref="async_mq_appender"/></logger>

最后就可以按照如下的方式進(jìn)行正常使用了：

private static Logger logger = LoggerFactory.getLogger("filelog_appender_logger");

注意： 此處需要注意log4j的一個性能問題。在log4j的conversionPattern中，匹配符最好不要出現(xiàn) C% L%通配符，壓測實(shí)踐表明，這兩個通配符會導(dǎo)致log4j打日志的效率降低10倍。

方案一很簡便，且剝離了接口直接依賴mq導(dǎo)致的性能問題。但是無法解決數(shù)據(jù)丟失的問題（但是我們其實(shí)可以在本地搞個策略落盤來不及處理的數(shù)據(jù)，可以大大的減少數(shù)據(jù)丟失的幾率）。但是很多的業(yè)務(wù)場景，是需要數(shù)據(jù)不丟失的，所以這就衍生出我們的另一套方案來。

方案二：增量消費(fèi)log4j日志

此種方式，是開啟worker在后臺增量消費(fèi)log4j的日志信息，和接口完全脫離。此種方式相比方案一，可以保證數(shù)據(jù)的不丟失，且可以做到完全不影響接口的ops。但是此種方式，由于是后臺worker在后臺啟動進(jìn)行掃描，會導(dǎo)致落庫的數(shù)據(jù)慢一些，比如一分鐘之后才落庫完畢。所以適用于對落庫數(shù)據(jù)實(shí)時性不高的場景。

具體的實(shí)現(xiàn)步驟如下：

首先，將需要進(jìn)行增量消費(fèi)的日志統(tǒng)一打到一個文件夾，以天為單位，每天生成一個帶時間戳日志文件。由于log4j不支持直接帶時間戳的日志文件生成，所以這里需要引入log4j.extras組件，然后配置log4j.xml如下：

之后在代碼中的申明方式如下：

private static Logger businessLogger = LoggerFactory.getLogger("file_rolling_logger");

最后在需要記錄日志的地方使用方式如下：

businessLogger.error(JsonUtils.toJSONString(myMessage))

這樣就可以將日志打印到一個單獨(dú)的文件中，且按照日期，每天生成一個。

然后，當(dāng)日志文件生成完畢后，我們就可以開啟我們的worker進(jìn)行增量消費(fèi)了，這里的增量消費(fèi)方式，我們選擇RandomAccessFile這個類來進(jìn)行，由于其獨(dú)特的位點(diǎn)讀取方式，可以使得我們非常方便的根據(jù)位點(diǎn)的位置來消費(fèi)增量文件，從而避免了逐行讀取這種低效率的實(shí)現(xiàn)方式。

注意，為每個日志文件都單獨(dú)創(chuàng)建了一個位點(diǎn)文件，里面存儲了對應(yīng)的文件的位點(diǎn)讀取信息。當(dāng)worker掃描開始的時候，會首先讀取位點(diǎn)文件里面的位點(diǎn)信息，然后找到相應(yīng)的日志文件，從位點(diǎn)信息位置開始進(jìn)行消費(fèi)。這就是整個增量消費(fèi)worker的核心。具體代碼實(shí)現(xiàn)如下(代碼太長，做了折疊)：

+ View Code

此種方式由于worker掃描是每隔一段時間啟動一次進(jìn)行消費(fèi)，所以導(dǎo)致數(shù)據(jù)從產(chǎn)生到入庫，可能經(jīng)歷時間超過一分鐘以上，但是在一些對數(shù)據(jù)延遲要求比較高的業(yè)務(wù)場景，比如庫存扣減，是不能容忍的，所以這里我們就引申出第三種做法，基于內(nèi)存文件隊(duì)列的異步日志消費(fèi)。

在此我向大家推薦一個架構(gòu)學(xué)習(xí)交流群。交流學(xué)習(xí)群號：478030634  里面會分享一些資深架構(gòu)師錄制的視頻錄像：有Spring，MyBatis，Netty源碼分析，高并發(fā)、高性能、分布式、微服務(wù)架構(gòu)的原理，JVM性能優(yōu)化、分布式架構(gòu)等這些成為架構(gòu)師必備的知識體系。還能領(lǐng)取免費(fèi)的學(xué)習(xí)資源，目前受益良多。

方案三：基于內(nèi)存文件隊(duì)列的異步日志消費(fèi)

由于方案一和方案二都嚴(yán)重依賴log4j，且方案本身都存在著要么丟數(shù)據(jù)，要么入庫時間長的缺點(diǎn)，所以都并不是那么盡如人意。但是本方案的做法，既解決了數(shù)據(jù)丟失的問題，又解決了數(shù)據(jù)入庫時間被拉長的尷尬，所以是終極解決之道。而且在大促銷過程中，此種方式經(jīng)歷了實(shí)戰(zhàn)檢驗(yàn)，可以大面積的推廣使用。

此方案中提到的內(nèi)存文件隊(duì)列，是我司自研的一款基于RandomAccessFile和MappedByteBuffer實(shí)現(xiàn)的內(nèi)存文件隊(duì)列。隊(duì)列核心使用了ArrayBlockingQueue，并提供了produce方法，進(jìn)行數(shù)據(jù)入管道操作，提供了consume方法，進(jìn)行數(shù)據(jù)出管道操作。而且后臺有一個worker一直啟動著，每隔5ms或者遍歷了100條數(shù)據(jù)之后，就將數(shù)據(jù)落盤一次，以防數(shù)據(jù)丟失。具體的設(shè)計(jì)，就這么多，感興趣的可以根據(jù)我提供的信息，自己實(shí)踐一下。

由于有此中間件的加持，數(shù)據(jù)生產(chǎn)的時候，只需要入壓入管道，然后消費(fèi)端進(jìn)行消費(fèi)即可。未被消費(fèi)的數(shù)據(jù)，會進(jìn)行落盤操作，謹(jǐn)防數(shù)據(jù)丟失。當(dāng)大促的時候，大量數(shù)據(jù)涌來的時候，管道滿了的情況下會阻塞接口，數(shù)據(jù)不會被拋棄。雖然可能會導(dǎo)致接口在那一瞬間無響應(yīng)，但是由于有落盤操作和消費(fèi)操作（此操作操控的是JVM堆外內(nèi)存數(shù)據(jù)，不受GC的影響，所以不會出現(xiàn)操作暫停的情況，為什么呢？因?yàn)橛昧薓appedByteBuffer），此種阻塞并未影響到接口整體的ops。

在實(shí)際使用的時候，ArrayBlockingQueue作為核心隊(duì)列，顯然是全局加鎖的，后續(xù)我們考慮升級為無鎖隊(duì)列，所以將會參考Netty中的有界無鎖隊(duì)列：MpscArrayQueue。預(yù)計(jì)性能將會再好一些。

受限于公司政策，我僅提供大致思路，但是不會提供具體代碼，有問題評論區(qū)交流吧。

上面就是在進(jìn)行異步日志消費(fèi)的時候，我所經(jīng)歷的三個階段，并且一步一步的優(yōu)化到目前的方式。雖然過程曲折，但是結(jié)果令人歡欣鼓舞。如果喜歡就給個推薦，后續(xù)我將會持續(xù)更新你所不知道的系列，以期達(dá)到拋磚引玉的效果。