最近碰到一個問題：客戶的伺服器程式偶爾出現請求響應過慢的情況，通過檢視日誌發現RSA驗證簽名的程式碼執行超過20秒，而正常情況下只需要16毫秒。

RSA證書是伺服器啟動就載入好的，不存在讀檔案慢的問題。看了一下那幾行程式碼，最有嫌疑的就是logback日誌列印的程式碼了。

查看了生產日誌配置，logback.xml裡配置為，每月生成一個資料夾，當月的日誌檔案都在同一資料夾下，比如201901資料夾下是2019年1月的所有日誌檔案。每個檔案配置為*.log.zip字尾，大小為10MB，也就是說10MB為大小分隔檔案。日誌列印類配置的是RollingFileAppender。

2019-1-30那一天，2019年1月資料夾下已經產生了5000多個日誌檔案，平均每天167個日誌檔案。

所以懷疑是日誌檔案太多，索引檔案的時間太長導致程式碼執行變慢，也就是說，要這樣懷疑的話，那就有一個前提：日誌列印是同步的，呼叫列印日誌的那行程式碼執行完了寫入檔案後，才會繼續向下執行業務程式碼。

我問了好幾個同事，都給我說日誌列印是非同步執行的，只有一個朋友說是同步的。我們都會以為列印日誌寫檔案比較消耗時間，日誌框架應該不會同步去寫檔案吧。然而事實卻是如果不配置非同步列印方式的話，就是以同步方式進行的日誌列印的。

斷點跟進程式碼發現是同步執行日誌寫入檔案的，只有當配置的appender是AsyncAppender時，日誌列印才是按照非同步方式列印的。

下面是同步列印日誌的情況：

logback.xml配置：

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    ......
</appender>

<root level="DEBUG">
    <appender-ref ref="CONSOLE"/>
</root>

執行程式碼：

LogWork.debug("111111111111");
System.out.println("2222222222222");

執行結果：

可以看到，執行結果是先把日誌框架的日誌列印執行完，再執行後面的業務程式碼的。所以是同步的。

下面是配置非同步列印日誌類的方法：

非同步列印日誌類AsyncAppender需要引用一個其他的日誌列印類，ASYNC只需要把需要列印的日誌寫入定義好的快取佇列裡，然後開啟一個守護執行緒去佇列裡取得日誌呼叫CONSOLE日誌列印器去寫入檔案。這樣日誌列印就是非同步進行的了。

logback.xml配置：

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    ......
</appender>

<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <discardingThreshold>0</discardingThreshold>
    <queueSize>100</queueSize>
    <neverBlock>true</neverBlock>
    <appender-ref ref="CONSOLE"/>
</appender>

<root level="INFO">
    <appender-ref ref="ASYNC"/>
</root>

執行程式碼：

LogWork.debug("111111111111");
System.out.println("2222222222222");

執行結果：

執行結果說明，呼叫日誌框架列印的程式碼執行後只是把要列印的日誌放入快取佇列，然後就繼續向下執行後面的程式碼，所以才先列印了後面的222222，之後才打印111111。說明是現在經過配置，日誌列印非同步工作的。

因文章開頭的問題引出了對日誌列印同步性的問題，所以研究了一番，不過最終也沒有和遇到的問題聯絡起來，因為就算知道了日誌是同步列印的，也沒法解釋為什麼偶爾出現幾分鐘程式碼執行特別慢。證據不充分，所以沒法給出結論。