本文目錄：

1. 同步打印日志中的坑

   1.1. 高并發(fā)場景下 logback 造成線程泄露
   1.2. 大量異常引發(fā)性能毛刺
2. 異步日志配置不當(dāng)造成線程泄露
3. 其他問題
4. 最佳實踐

一、同步打印日志中的坑

1.1 高并發(fā)場景下 logback 造成線程泄露

調(diào)用 logback 去打印日志的時候是會加鎖的，加鎖的位置在：

// ch.qos.logback.core.OutputStreamAppender#writeBytes
private void writeBytes(byte[] byteArray) throws IOException {
    if (byteArray != null && byteArray.length != 0) {
        this.lock.lock();
        try {
            this.outputStream.write(byteArray);
            if (this.immediateFlush) {
                this.outputStream.flush();
            }
        } finally {
            this.lock.unlock();
        }

    }
}

這就意味著同一個appender的日志寫是串行的，在高并發(fā)的場景下因為有鎖的爭用現(xiàn)象，所以看似很簡單的一行日志，耗費(fèi)的時間卻不少。接下來我們在本地簡單的模擬一下高并發(fā)的場景，并記錄打一行日志的耗時是多少

public static void main(String[] args) {
    ExecutorService threadPool = new ThreadPoolExecutor(500, 750, 20, TimeUnit.MINUTES, new ArrayBlockingQueue<>(1),
                                                        new ThreadFactoryBuilder().setNameFormat("test-log-thread").build(), new ThreadPoolExecutor.CallerRunsPolicy());
    for (int i = 0; i < 750; i++) {
        LoggerExecutor commonExecutor = new LoggerExecutor();
        threadPool.submit(commonExecutor);
    }
}
static class LoggerExecutor implements Runnable {
    @SneakyThrows
    @Override
    public void run() {
        while (true) {
            long start = System.currentTimeMillis();
            logger.info("log info message at {}", System.currentTimeMillis());
            long end = System.currentTimeMillis();
            long time = end - start;
            System.out.println(time);
        }
    }
}

需要說明的是，現(xiàn)實中高并發(fā)的請求應(yīng)當(dāng)用一個線程池向另一個線程池反復(fù)提交任務(wù)來模擬，這里我們簡化了這個過程。

上圖是我記錄下來的logger.info的耗時曲線，從這張統(tǒng)計圖上可以看到，當(dāng)并發(fā)量上來之后鎖爭用的情況加劇，僅僅是打印一行info日志就可能花費(fèi) 20-40ms(作為對比，在我的機(jī)器上單線程打印一行日志通常是 1-2ms)，而且圖上有比較明顯的毛刺，打印日志的耗時超過了 100ms，毛刺的原因在于OutputStream在緩存區(qū)滿了后要執(zhí)行刷盤動作，但是在真正大流量應(yīng)用中這種毛刺是致命的，可能導(dǎo)致RPC框架的線程池被吃光，正常業(yè)務(wù)服務(wù)的成功率下降。所以在高并發(fā)大流量的場景下info日志的打印一定要謹(jǐn)慎。

1.2 大量異常引發(fā)性能毛刺

在上一小節(jié)中我們提到，高并發(fā)場景下info日志要謹(jǐn)慎打印，一般我們只記錄系統(tǒng)異常的日志。我們把剛才的代碼片段做一個小的修改，改為調(diào)用logger.error打印日志，然后再統(tǒng)計下這行代碼的耗時

// 驅(qū)動代碼同1.1節(jié)，所以這里省略
static class LoggerExecutor implements Runnable {
    @SneakyThrows
    @Override
    public void run() {
        while (true) {
            long start = System.currentTimeMillis();
            //logger.info("log info message at {}", System.currentTimeMillis());
            logger.error("log info message occurs error： {}", new RuntimeException());
            long end = System.currentTimeMillis();
            long time = end - start;
            System.out.println(time);
        }
    }
}

與 1.1 節(jié)相比，一個很明顯的變化就是error日志的執(zhí)行平均耗時到了 40-50ms，要比 1.1 節(jié)中的info日志慢不少，這是為什么呢？原因就在于調(diào)用logger.error(String, Throwable)時為了打印堆棧加載了每個調(diào)用節(jié)點的class，代碼在：

//ch.qos.logback.classic.spi.PackagingDataCalculator#computeBySTEP
private ClassPackagingData computeBySTEP(StackTraceElementProxy step, ClassLoader lastExactClassLoader) {
    String className = step.ste.getClassName();
    ClassPackagingData cpd = cache.get(className);
    if (cpd != null) {
        return cpd;
    }
    // 注意這行代碼
    Class type = bestEffortLoadClass(lastExactClassLoader, className);
    String version = getImplementationVersion(type);
    String codeLocation = getCodeLocation(type);
    cpd = new ClassPackagingData(codeLocation, version, false);
    cache.put(className, cpd);
    return cpd;
}

在bestEffortLoadClass中則會嘗試類加載:

private Class bestEffortLoadClass(ClassLoader lastGuaranteedClassLoader, String className) {
    Class result = loadClass(lastGuaranteedClassLoader, className);
    if (result != null) {
        return result;
    }
    ClassLoader tccl = Thread.currentThread().getContextClassLoader();
    if (tccl != lastGuaranteedClassLoader) {
        result = loadClass(tccl, className);
    }
    if (result != null) {
        return result;
    }

    try {
        return Class.forName(className);
    } catch (ClassNotFoundException e1) {
        return null;
    } catch (NoClassDefFoundError e1) {
        return null;
    } catch (Exception e) {
        e.printStackTrace(); // this is unexpected
        return null;
    }
}

// ch.qos.logback.classic.spi.PackagingDataCalculator#loadClass
private Class loadClass(ClassLoader cl, String className) {
    if (cl == null) {
        return null;
    }
    try {
        return cl.loadClass(className);
    } catch (ClassNotFoundException e1) {
        return null;
    } catch (NoClassDefFoundError e1) {
        return null;
    } catch (Exception e) {
        e.printStackTrace(); // this is unexpected
        return null;
    }
}

java.lang.ClassLoader#loadClass(java.lang.String)這個方法就是我們熟知的加載類的接口，其實會在className維度加鎖。到這里為什么logger.error比logger.info慢多大家應(yīng)該就猜到了，logger.error會打印出異常的堆棧，在高并發(fā)的場景下如果某個接口頻繁拋異常，那在打印error日志的時候要各個線程要先去加載異常堆棧上各個類信息，產(chǎn)生鎖競爭，然后才會在appender維度排隊。一個常見的現(xiàn)實場景是下游服務(wù)限流或者直接宕機(jī)了，容易因為logback引發(fā)系統(tǒng)的毛刺。

二、異步日志配置不當(dāng)造成線程泄露

其實在高并發(fā)的場景下，一般都會將日志配置為異步打印，其原理大概如下圖所示：

AsyncAppender將Logging Event扔到一個隊列里，然后會有一個單獨的線程從隊列中消費(fèi)LoggingEvent，并派發(fā)到具體要干活的Appender中，因為避免了直接直接調(diào)用writeBytes，所以性能應(yīng)該有非常大的提升。我們對logback的配置稍作改動，采取異步的方式打印日志：

<appender name="FILE" class="ch.qos.logback.core.FileAppender">
  <file>/Users/idealism/Desktop/log.txt</file>
  <encoder>
    <pattern>%logger{35} - %msg%n</pattern>
  </encoder>
</appender>
<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
  <appender-ref ref="FILE" />
</appender>
<root level="DEBUG">
  <appender-ref ref="ASYNC"/>   
</root>
</configuration>

并采樣了每次打印日志的耗時如下圖所示：

令人震驚的一幕出現(xiàn)了，在并發(fā)量比較大的場景下，異步打印日志的的性能與同步相比竟然差了 10 倍！這是為什么呢？上文說到，logback異步日志的實現(xiàn)原理是一個生產(chǎn)者-消費(fèi)者模型，問題在于在大流量的場景下，分配線程這個單線程的消費(fèi)能力是趕不上生產(chǎn)能力的，最后導(dǎo)致所有的線程在日志打印的阻塞隊列上排隊。此時通過arthas也可以看到線程的排隊情況，如果這是線上的業(yè)務(wù)系統(tǒng)，業(yè)務(wù)線程早被日志的阻塞隊列吃光了，會引起業(yè)務(wù)響應(yīng)異常

[arthas@9341]$ thread
Threads Total: 780, NEW: 0, RUNNABLE: 13, BLOCKED: 745, WAITING: 4, TIMED_WAITIN
G: 3, TERMINATED: 0, Internal threads: 15
ID NAME                GROUP     PRIORI STATE  %CPU  DELTA_ TIME   INTER DAEMON
10 AsyncAppender-Worke main      5      RUNNAB 43.01 0.090  0:13.7 false true
77 arthas-command-exec system    5      RUNNAB 4.9   0.010  0:0.02 false true
39 test-log-thread     main      5      BLOCKE 0.75  0.001  0:0.14 false false
71 test-log-thread     main      5      BLOCKE 0.71  0.001  0:0.15 false false
37 test-log-thread     main      5      BLOCKE 0.71  0.001  0:0.14 false false
74 test-log-thread     main      5      BLOCKE 0.69  0.001  0:0.15 false false
67 test-log-thread     main      5      BLOCKE 0.69  0.001  0:0.14 false false
-1 C2 CompilerThread2  -         -1     -      0.68  0.001  0:1.68 false true
69 test-log-thread     main      5      BLOCKE 0.66  0.001  0:0.15 false false
55 test-log-thread     main      5      BLOCKE 0.66  0.001  0:0.14 false false
38 test-log-thread     main      5      BLOCKE 0.65  0.001  0:0.15 false false
36 test-log-thread     main      5      BLOCKE 0.65  0.001  0:0.14 false false
28 test-log-thread     main      5      BLOCKE 0.65  0.001  0:0.15 false false
50 test-log-thread     main      5      BLOCKE 0.65  0.001  0:0.14 false false
36 test-log-thread     main      5      BLOCKE 0.64  0.001  0:0.14 false false

三、其他問題

除了上面提到的幾個在高并發(fā)大流量場景下特有的坑外，還有一些其他的坑這里列一下，因為網(wǎng)上的博客比較多了，這里不再贅述

1. https://www.elietio.xyz/posts/f6b1711c.html《低版本 bug 導(dǎo)致 totalSizeCap 參數(shù)不生效》
2. logback版本過低導(dǎo)致SizeAndTimeBasedRollingPolicy不生效的問題

四、最佳實踐

應(yīng)當(dāng)遵循以下幾個原則：

【最佳實踐一】日志工具對象的logger應(yīng)當(dāng)聲明為private static final

1. 聲明為private是為了安全性考慮，防止logger被其他類非法使用
2. 聲明為static和final則是因為在類的聲明周期內(nèi)無需變更logger，并且占用內(nèi)存也更小

【最佳實踐二】日志字符串通過"+"拼接即占用了額外的內(nèi)存，也不直觀，應(yīng)當(dāng)使用占位符

【最佳實踐三】日志內(nèi)容和日志級別相符合

1. debug和trace一般是開發(fā)者調(diào)試程序使用，線上應(yīng)關(guān)閉這類日志
2. info日志應(yīng)當(dāng)記錄重要且無風(fēng)險的信息，如上下文初始化，定時任務(wù)開始執(zhí)行或者遠(yuǎn)程連接建立等場合
3. warn日志應(yīng)當(dāng)記錄可能有風(fēng)險，但是不會影響系統(tǒng)繼續(xù)運(yùn)行的錯誤，如系統(tǒng)參數(shù)配置錯誤，用戶請求參數(shù)不正確等?；蛘呤窃谝恍┖臅r異常的場景，如一次請求超時，一次sql執(zhí)行超過 2 秒等
4. error日志用于程序出錯打印堆棧，不應(yīng)該輸出程序問題之外的其他信息

【最佳實踐四】高并發(fā)系統(tǒng)應(yīng)少打或不打info日志，且應(yīng)當(dāng)配置為異步日志，當(dāng)阻塞隊列滿時采取丟日志的策略，以保證業(yè)務(wù)系統(tǒng)正常運(yùn)行

點擊 閱讀原文  跳轉(zhuǎn)至Java開源消息推送平臺項目倉庫