一、背景

在日常部門OpsReview過程中，部門內多次遇到應用容器所在的宿主機磁碟繁忙導致的介面響應緩慢，TP99增高等影響服務效能的問題，其中比較有效的解決方案是開啟日誌的非同步列印，可以有效避免同步日誌列印在磁碟IO高起的情況下拖慢業務執行緒的執行效率。

部門內的jimkv應用爲了配合倉做切量，在最近將日誌列印功能降到了INFO級別，開啟日誌列印以便問題排查，期間遇到過一次因宿主機磁碟繁忙引起TP99升高導致多個comsumer超時而影響了個別業務。

經過評估遂對組內的兩個基礎應用（pk和jimkv）切換為非同步日誌列印功能，在pk上線一週後觀察無異常情況後對jimkv也同樣切換。

具體切換方法為在專案裡和log4j2.xml同級目錄下建立log4j2.component.properties檔案，配置如下：

# 所有Logger非同步配置
log4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
# 日誌佇列滿的處理策略，丟棄
log4j2.asyncQueueFullPolicy=Discard
# 丟棄日誌的級別
log4j2.discardThreshold=ERROR

但是在jimkv開啟3天后收到了JVM記憶體使用率超高的告警電話，擔心會發生OOM而且時值週五晚就先將所有機器重啟了一遍，最後一臺執行jmap dump等命令來保留現場以備後續排查。

二、現象

2.1、容器和JVM配置

容器硬體配置：4C8G

JVM配置：-Xss256k -Xms4G -Xmx4G -XX:MaxMetaspaceSize=512m -XX:MetaspaceSize=512m -XX:MaxDirectMemorySize=256m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./java_pid.hprof -Dbasedir=/export/App -Dfile.encoding=UTF-8

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

2.2、JVM監控圖

下圖為開啟非同步日誌後的GC和堆記憶體監控圖，在左下角的堆記憶體圖可以明顯的看到堆記憶體的上漲情況，特別是白天業務量大的時候，按此趨勢正好3天就能把堆記憶體漲到90%的告警閾值。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

下圖為未開啟非同步記錄日誌的同步記錄日誌的監控圖，可以看到JVM的堆空間是一個很平直的波動，並不會隨時間的增加而上漲。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

下圖是非同步和同步的對比圖，紅色的是開啟了非同步記錄日誌：

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

三、排查過程

分析可能出現問題的原因：

1、大日誌日誌導致的記憶體溢位；

2、日誌列印太多導致的記憶體溢位；

3、log4j非同步日誌的隱藏問題/bug；

3.1、方向一：日誌列印太多

首先排查上述可能的原因1&2，可以肯定的是跟日誌有關，因為這個應用基本沒有業務邏輯，也不存在大量的計算，最多的是日誌列印，那為什麼不減少日誌列印或乾脆關閉日誌列印呢，是的，這個應用平時是關閉日誌列印的，最近是爲了配合倉做切量纔打開的日誌列印。

那麼問題是由日誌多導致的嗎，說是，也可以說也不是，不是的原因是因為在開啟非同步日誌之前已開啟日誌列印一段時間了，沒有出現記憶體溢位的情況，所以推測日誌多不是根因，它最多算是誘因。

那關閉能解決嗎？直覺告訴我肯定是能解決的，但好奇心驅使我沒有去這麼做，一是目前沒有因為記憶體溢位出現線上問題；二是還沒有出現FGC，JVM的PS收集器是可能承受記憶體在幾乎滿的情況下透過FGC來清理記憶體的，我們可以留一臺觀察其是否會發生FGC來驗證上述的想法；

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

上圖是留的一臺機器，在某日的上午近10點果然發生了一次FGC，可以看到左下角的堆記憶體一下降到不到500M，接著如期繼續上漲，說明其不會發生OOM，也不會對線上業務產生影響，可以放心的開啟非同步日誌列印並隨時dump堆記憶體現場下來分析。

這個現象最終並不會發生OOM，所以不能稱其為記憶體溢位或洩漏，只能算作堆記憶體快速上漲（3天耗盡了4G記憶體），說明有不停的物件在YGC後被挪到了年老代，最後被FGC掉。

3.2、方向二：大日誌

那既不是日誌列印多引起的，會是大日誌列印引起的嗎？下面我們來看dump出的堆記憶體檔案。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

透過VisualVM開啟dump下來的檔案，按照例項數來倒序排，在排除char、byte、int等Java基本型別後，佔據第一的是java.lang.StackTraceElement，對其進行重點排查。

StackTraceElement都是在StackTraceElement[]這個陣列物件來，我們開啟java.lang.StackTraceElement[]來看。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

圖3.2.1

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

圖3.2.2

可以明顯看到java.lang.StackTraceElement[]裡的資訊是每一個執行緒所經過的類和方法路徑，從執行緒入口到當前所在類方法一一記錄。

此處並沒有大日誌，也沒有日誌大的相關資訊，此時開始推測會不會是列印的異常日誌導致的，因為應用裡有一個頻繁的業務異常會導致大量的堆疊資訊列印，但非同步日誌開啟前後並未有其他變化，而且也找不出可以證實的其他關鍵資訊，只能留下來一個大大的問號【？】。

3.3、方向三：log4j非同步日誌bug

基本可以排除是日誌多和大日誌引起的原因後，開始在各大知識庫裡搜尋公開的log4j非同步日誌的bug，包括在諮詢了搜索引擎和大模型後，並未得到有明確關於log4j的bug相關資訊，內心也不相信強大的log4j框架有bug，就算有bug就這麼讓我遇到了嗎，每次抽獎都輪不到的我不可能有這種運氣。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

繼續回頭看了很多遍dump出的堆檔案，在多次看著char[]佔用71%的堆空間情況下，終於忍不住點開了char[]，在看到滿屏的日誌資訊後，頓感眼前一片光明，難道真的是大日誌導致的堆記憶體空間上漲啊。。。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

粗略的計算了下，第一大的char[]佔據了3M的空間，而且char有474萬個例項之多，果然是大日誌搞的鬼。

隨後進行了更進一步排查，為啥在開啟非同步日誌後會出現這麼大量的char[]陣列出現呢？

咱們知道JVM是分代進行垃圾回收的，物件例項在一次YGC後如果還存活的話會被放在Survival區，並多次YGC後虛擬機器會將還存活的物件例項從Young區挪到Old區。

從前面的堆記憶體圖並結合JVM的分代垃圾回收知識，我們看出在每次YGC後總會有一小部分的物件例項被挪到了年老代裡。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

那為什麼同步日誌的時候沒有出現這種情況呢，也就是說沒有物件例項在多次YGC後還是存活的。

我們開始在log4j非同步日誌原理和log4j、disruptor的原始碼裡找答案。

關於log4j非同步日誌原理大家可以在網上搜索相關文章，這裏不做冗餘介紹了，我們直接從非同步日誌用到的RingBuffer和RingBufferLogEvent裡開始查詢相關資訊。

在org.apache.logging.log4j.core.async.RingBufferLogEvent#clear方法裡我們看到對messageText（儲存要列印的日誌內容）進行了trim操作，往下追了幾層，在java.util.Arrays#copyOf(char[], int)裡進行了new char操作，也就是對於超過org.apache.logging.log4j.core.util.Constants#MAX_REUSABLE_MESSAGE_SIZE的日誌內容進行了截斷，而截斷是透過底層java.util.Arrays#copyOf(char[], int)一個字元陣列來實現的。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

這裏有兩個前置條件纔會進行new char[]操作

首先是org.apache.logging.log4j.core.util.Constants#ENABLE_THREADLOCALS要為True，我們來看看它的相關原始碼。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

這裏因為不是web應用，所以IS_WEB_APP=false，同時也沒有配置log4j2.enable.threadlocals，預設為true。

所以這裏org.apache.logging.log4j.core.util.Constants#ENABLE_THREADLOCALS=ture確認無疑。

我們再來看看org.apache.logging.log4j.core.util.Constants#MAX_REUSABLE_MESSAGE_SIZE的值。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

可以看到如果沒有設定log4j.maxReusableMsgSize的值，MAX_REUSABLE_MESSAGE_SIZE預設值是等於518。

也就是日誌大小在大於518個字元的時候是會被截斷，而截斷是透過Arrays.copyOf的方式new char[]實現的。

我們決定關閉log4j2.enable.threadlocals，將其設定為false來驗證是否是messageText被截斷導致的堆記憶體上漲現象。

log4j2.enable.threadlocals=false

上線後第二天的堆記憶體監控圖，可以看出確實沒有出現堆記憶體上漲的情況。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

3.4、方向四：無垃圾穩態日誌

截止到目前堆記憶體上漲的問題似乎找到了原因，而且也透過配置threadlocals解決了問題，為什麼說似乎呢，後面會有解釋，先來看看在前面的排查過程中我們還發現了什麼？

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

紅框裡的“LOG4J2-1270 no-GC”，這似乎是使用者提交的一個issue，難道真的有bug？又一次帶著大大的問號【？】去log4j的官網進行了搜尋，issues.apache.org/jira/browse…，這是有關“LOG4J2-1270”的issue，但並沒有發現有用的資訊。

倒是紅框裡最後的“no-GC”是log4j非同步日誌的一個特性，詳細的可以訪問log4j日誌的官網檢視，地址是logging.apache.org/log4j/2.x/m…

《Garbage-free Steady State Logging》確實和前面看到的原始碼相符，在ENABLE_THREADLOCALS=ture的情況下除了會重用RingBufferLogEvent等外，RingBufferLogEvent裡的messageText和parameters也是會被重用的，不然就會被messageText = null;和parameters = null;。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

但是這裏說的是“no-GC”，而現在的現象是出現了Garbage，並且是用FGC的，原始碼422行的備註

// ensure that excessively long char[] arrays are not kept in memory forever

翻譯過來也是說的“確保過長的char[]陣列不會永遠儲存在記憶體中”，似乎是哪裏對不上了？

我們回到messageText上來，仔細想想非同步日誌雖然是重用RingBufferLogEvent，但每次在日誌輸出給磁碟IO後如果日誌長度大於518個字元是要被new出來的char[]替掉的，也就是日誌內容大於518個字元的char[]陣列是活不過多次YGC的，是不可能進入到年老代的。

似乎和我們的《Garbage-free Steady State Logging》是對應的，請允許我再一次用似乎這個詞，因為和現象確實是朝著兩個方向走。

我們決定寫一個本地測試類，來驗證StringBuilders.trimToMaxSize在截斷字元陣列後是否會在多次GC後依然存活於堆記憶體中。

以下是測試類的程式碼，首先建立一個512長度的StringBuilder，透過迴圈append放入32個A和480個B，sleep30秒用來操作dump堆記憶體檔案，再將messageText進行截斷，再次操作dump，分別分析兩次dump出的檔案，觀察char[]陣列的內容。

public static void main(String[] args) throws InterruptedException {
    StringBuilder messageText = new StringBuilder(512);

    for (int i = 0; i < 32; i++) {
        messageText.append('A');
    }
    for (int i = 0; i < 480; i++) {
        messageText.append('B');
    }

    Thread.sleep(1000 * 30);

    StringBuilders.trimToMaxSize(messageText, 256);

    Thread.sleep(1000 * 1000);
}

JVM啟動引數

-XX:InitialHeapSize=20M
-XX:MaxHeapSize=20M
-XX:MaxNewSize=10M
-XX:NewSize=10M
-XX:+PrintGC
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-Xloggc:./gc.log

第一次dump出的messageText是1040B。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

第二次dump出的messageText是528B，是被截斷後new出來的char[]，堆記憶體中經過一次GC是沒有512長度的StringBuilder，說明第一個StringBuilder在GC後被清理掉了。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

下面是兩次操作的GC日誌。

OpenJDK 64-Bit Server VM (25.345-b01) for bsd-amd64 JRE (1.8.0_345-b01), built on Aug  2 2022 11:46:33 by "jenkins" with gcc 4.2.1 Compatible Apple LLVM 10.0.1 (clang-1001.0.46.4)
Memory: 4k page, physical 16777216k(12992k free)

/proc/meminfo:

CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:NewSize=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
19.724: [GC (Heap Dump Initiated GC) [PSYoungGen: 8165K->1024K(9216K)] 8973K->2519K(19456K), 0.0091384 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 
19.734: [Full GC (Heap Dump Initiated GC) [PSYoungGen: 1024K->0K(9216K)] [ParOldGen: 1495K->2231K(10240K)] 2519K->2231K(19456K), [Metaspace: 9337K->9337K(1058816K)], 0.0119249 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
92.727: [GC (Heap Dump Initiated GC) [PSYoungGen: 2527K->288K(9216K)] 4758K->2519K(19456K), 0.0059243 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 
92.733: [Full GC (Heap Dump Initiated GC) [PSYoungGen: 288K->0K(9216K)] [ParOldGen: 2231K->1929K(10240K)] 2519K->1929K(19456K), [Metaspace: 9823K->9738K(1058816K)], 0.0215627 secs] [Times: user=0.05 sys=0.01, real=0.02 secs]

透過上面的測試實驗證實了Log4j的非同步日誌確認是no GC的。

難道有別的物件指向了RingBufferLogEvent裡的messageText，我們又翻了幾遍原始碼，仍是沒有找到有指向messageText的物件，此刻陷入了僵局。

此後我們又回頭繼續看dump的堆記憶體檔案，在多次開啟char[]例項後看到了一個現象，就在大概在6000多個char[]以後有大量的1056B的char[]。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

從上面兩個圖我們可以看到從近7000到221萬的地方，大概有200多萬的char[]例項都是1056B，難道這是大於518個字元後截斷時被new出來的新char[]物件？帶著這個疑問重新回到原始碼來找答案。

既然1056B和518個字元是能對應上，也就是說我們現在的方向是對的，讓我們繼續往下走走，new出來的char[]再被使用的時候會怎麼樣呢

如果大於518個字元還是會被替掉，還是會被YGC掉，因為潛意識裏一直覺得是大日誌導致的，所以一直在考慮大日誌也就是肯定是大於518個字元。突然轉念一想，大於518個字元，如果小於呢，小於等於518個字元會怎麼樣。

如果小於等於518個字元的話......，也就是會重用這個new出來的char[]，這樣在多次YGC後這個例項就會從Eden區到Survival區再到Old區，如果這個時候來一個大於518個字元的日誌呢，O(∩_∩)O哈哈~

畫面感來了，那個518字元的char[]被遺棄在了Old區，Young區裡多了一個大於518個字元的新char[]例項。

爲了證實上面的推測我們從java.lang.AbstractStringBuilder#append(java.lang.CharSequence)來找答案。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

可以看到在append的時候如果char[]的長度不夠的話是會進行擴容的，而擴容也是透過java.util.Arrays#copyOf(char[], int)，也就是new char[]。

到這問題基本就已經很清晰了，原因就是我們的日誌列印從小日誌到大日誌都有，不等長，日誌內容是各業務系統在生產過程中的上下文資訊，有長有短。

RingBufferLogEvent裡的messageText在來來回回的重用過程中，經過多次YGC就一定會有機會將518個字元長度的char[]遺棄在了Old區，長時間積累就導致了JVM堆空間不斷上漲，最後經過一次FGC就能清除掉所有的char[]垃圾物件。

JVM堆記憶體示意圖，在多次GC後char[518]物件被挪到了old區，在某一次遇到大於518個字元日誌的時候，在eden區new了一個新的char[]陣列，原來的char[518]被留在了old區變成了垃圾物件。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

四、解決方案

4.1、設定log4j2.enable.threadlocals

log4j2.enable.threadlocals=false

透過在log4j2.component.properties檔案裡設定log4j2.enable.threadlocals=false可以關閉log4j的threadlocals從而使log4j的Garbage-free失效。每次都將messageText=null，這樣就能在YGC的時候清理掉日誌字元例項。

4.2、設定log4j.maxReusableMsgSize

log4j.maxReusableMsgSize=一個比較長的字元長度

如果可以確定日誌大小或者是日誌最大的長度，可以根據日誌長度設定log4j.maxReusableMsgSize一個合理的值，使其不會出現字元陣列頻繁的trim和ensureCapacity，從而避免在Young區new char[]陣列。

4.3、控制日誌輸出長度

這個其實是最好的方案，因為日誌本來就不應該輸出長日誌內容，無論是從效能、儲存、檢視和排查，大日誌輸出列印都不是一個好的設計。

所以在日誌列印的地方控制日誌長度，比如擷取固定的日誌長度，或者是計算下所要列印的日誌長度，如果大於一定值，只打印日誌長度而不列印日誌內容。

五、寫在最後

5.1、Garbage-free特性

由於篇幅及時間問題，我們沒有做本地的壓測對比，暫借用官網的一個壓測結果，可以看到log4j的Garbage-free特性還是對應用的效能還是有很大的提升，所以不建議用上面的解決方案1來放棄使用非同步日誌的Garbage-free特性。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

logging.apache.org/log4j/2.x/m…

5.2、關於ringBufferSize

在排查RingBuffer的過程中發現在dump出的堆空間檔案裡org.apache.logging.log4j.core.async.RingBufferLogEvent的例項數是4096，並不是官網所說的256 * 1024個RingBufferLogEvent

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

帶著這個疑問重新查了下log4j的原始碼，在org.apache.logging.log4j.core.async.DisruptorUtil#calculateRingBufferSize中發現了端倪。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

在Constants.ENABLE_THREADLOCALS=true的情況下，ringBufferSize是等於RINGBUFFER_NO_GC_DEFAULT_SIZE = 4 * 1024，正好等於4096。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

Log4j非同步日誌官網地址：logging.apache.org/log4j/2.x/m…

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

5.3、最後選擇的解決方案

我們最後選擇的是方案3，透過列印日誌內容長度，同時對日誌進行了截斷，只打印前256個字元。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程

實際的日誌列印內容，日誌內容是被截斷的。

php複製程式碼2024-04-17 19:36:43.321-3445306.59406.17133538031451831-jdos_jdl-oms-outbound-worker INFO -[JSF-BZ-22000-12-T-3] com.jd.eclp.jimkv.rpc.EclpJimKVClientAdapter.getByKey(EclpJimKVClientAdapter.java:28) -key=jfs/kveclp/0/1713342604406/2698/12aa38e8324fa5817d0b6bc2065b9555,result.length=267,result={"customerPrintInfo":"{"orderExtendInfo":{"huashengSignJfs":"1","huashengIdcardJfs":"************132914","huashengSignStandardJfs":""}}","extendPrintInfo":"{"CNTemplate":"0","thirdPayment":"null","receiveMode":"null","sendMode":

上線後的堆記憶體監控圖，沒有再出現多次YGC後堆記憶體逐步上漲的情況。

記錄 log4j 日誌列印導致的 JVM 記憶體洩漏問題的排查過程