天天看點

實戰記一次JVM堆外記憶體洩露Bug的查找

作者:JAVA後端架構
實戰記一次JVM堆外記憶體洩露Bug的查找

前言

JVM的堆外記憶體洩露的定位一直是個比較棘手的問題。此次的Bug查找從堆内記憶體的洩露反推出堆外記憶體,同時對實體記憶體的使用做了定量的分析,進而實錘了Bug的源頭。

記憶體洩露Bug現場

一個線上穩定運作了三年的系統,從實體機遷移到docker環境後,運作了一段時間,突然被監控系統發出了某些執行個體不可用的報警。所幸有負載均衡,可以自動下掉節點,如下圖所示:

實戰記一次JVM堆外記憶體洩露Bug的查找

登入到對應機器上後,發現由于記憶體占用太大,觸發OOM,然後被linux系統本身給kill了。

應急措施

緊急在出問題的執行個體上再次啟動應用,啟動後,記憶體占用正常,一切Okay。

奇怪現象

目前設定的最大堆記憶體是1792M,如下所示:

-Xmx1792m -Xms1792m -Xmn900m -XX:PermSi
ze=256m -XX:MaxPermSize=256m -server -Xss512k
           

檢視作業系統層面的監控,發現記憶體占用情況如下圖所示:

實戰記一次JVM堆外記憶體洩露Bug的查找

上圖藍色的線表示總的記憶體使用量,發現一直漲到了4G後,超出了系統限制。

很明顯,有堆外記憶體洩露了。

查找線索

gc日志

一般出現記憶體洩露,筆者立馬想到的就是檢視當時的gc日志。

本身應用所采用架構會定時列印出對應的gc日志,遂檢視,發現gc日志一切正常。對應日志如下:

實戰記一次JVM堆外記憶體洩露Bug的查找

檢視了當天的所有gc日志,發現記憶體始終會回落到170M左右,并無明顯的增加。要知道JVM程序本身占用的記憶體可是接近4G(加上其它程序,例如日志程序就已經到4G了),進一步确認是堆外記憶體導緻。

排查代碼

打開線上服務對應對應代碼,查了一圈,發現沒有任何地方顯式利用堆外記憶體,其沒有依賴任何額外的native方法。關于網絡IO的代碼也是托管給Tomcat,很明顯,作為一個全世界廣泛流行的Web伺服器,Tomcat不大可能有堆外記憶體洩露。

進一步查找

由于在代碼層面沒有發現堆外記憶體的痕迹,那就繼續找些其它的資訊,希望能發現蛛絲馬迹。

Dump出JVM的Heap堆

由于線上出問題的Server已經被kill,還好有其它幾台,登上去發現它們也 占用了很大的堆外記憶體,隻是還沒有到觸發OOM的臨界點而已。于是就趕緊用jmap dump了兩台機器中應用JVM的堆情況,這兩台留做現場保留不動,然後将其它機器迅速重新開機,以防同時被OOM導緻服務不可用。

使用如下指令dump:

jmap -dump:format=b,file=heap.bin [pid]
           

使用MAT分析Heap檔案

挑了一個heap檔案進行分析,堆的使用情況如下圖所示:

實戰記一次JVM堆外記憶體洩露Bug的查找

一共用了200多M,和之前gc檔案列印出來的170M相差不大,遠遠沒有到4G的程度。

不得不說MAT是個非常好用的工具,它可以提示你可能記憶體洩露的點:

實戰記一次JVM堆外記憶體洩露Bug的查找

這個cachedBnsClient類有12452個執行個體,占用了整個堆的61.92%。

檢視了另一個heap檔案,發現也是同樣的情況。這個地方肯定有記憶體洩露,但是也占用了130多M,和4G相差甚遠。

檢視對應的代碼

系統中大部分對于CachedBnsClient的調用,都是通過注解Autowired的,這部分執行個體數很少。

唯一頻繁産生此類執行個體的代碼如下所示:

@Override
    public void fun() {
            BnsClient bnsClient = new CachedBnsClient();
          // do something
            return  ;
    }
           

此CachedBnsClient僅僅在方法體内使用,并沒有逃逸到外面,再看此類本身

public class CachedBnsClient   {
    private ConcurrentHashMap<String, List<String>> authCache = new ConcurrentHashMap<String, List<String>>();
    private ConcurrentHashMap<String, List<URI>> validUriCache = new ConcurrentHashMap<String, List<URI>>();
    private ConcurrentHashMap<String, List<URI>> uriCache = new ConcurrentHashMap<String, List<URI>>();
    ......
}
           

沒有任何static變量,同時也沒有往任何全局變量注冊自身。換言之,在類的成員(Member)中,是不可能出現記憶體洩露的。

當時隻粗略的過了一過成員變量,回過頭來細想,還是漏了不少地方的。

更多資訊

由于代碼排查下來,感覺這塊不應該出現記憶體洩露(但是事實确是如此的打臉)。這個類也沒有顯式用到堆外記憶體,而且隻占了130M,和4G比起來微不足道,還是先去追查主要沖突再說。

使用jstack dump線程資訊

現場資訊越多,越能找出蛛絲馬迹。先用jstack把線程資訊dump下來看下。

這一看,立馬發現了不同,除了正常的IO線程以及架構本身的一些守護線程外,竟然還多出來了12563多個線程。

"Thread-5" daemon prio=10 tid=0x00007fb79426e000 nid=0x7346 waiting on condition [0x00007fb7b5678000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at com.xxxxx.CachedBnsClient$1.run(CachedBnsClient.java:62)
           

而且這些正好是運作再CachedBnsClient的run方法上面!這些特定線程的數量正好是12452個,和cachedBnsClient數量一緻!

再次check對應代碼

原來剛才看CachedBnsClient代碼的時候遺漏掉了一個關鍵的點!

public CachedBnsClient(BnsClient client) {
        super();
        this.backendClient = client;
        new Thread() {
            @Override
            public void run() {
                for (; ; ) {
                    refreshCache();
                    try {
                        Thread.sleep(60 * 1000);
                    } catch (InterruptedException e) {
                        logger.error("出錯", e);
                    }
                }
            }
            ......
        }.start();
    }
           

這段代碼是CachedBnsClient的構造函數,其在裡面建立了一個無限循環的線程,每隔60s啟動一次重新整理一下裡面的緩存!

找到關鍵點

在看到12452個等待在CachedBnsClient.run的業務的一瞬間筆者就意識到,肯定是這邊的線程導緻對外記憶體洩露了。下面就是根據線程大小計算其洩露記憶體量是不是确實能夠引起OOM了。

發現記憶體計算對不上

由于我們這邊設定的Xss是512K,即一個線程棧大小是512K,而由于線程共享其它MM單元(線程本地記憶體是是現線上程棧上的),是以實際線程堆外記憶體占用數量也是512K。進行如下計算:

12563 * 512K = 6331M = 6.3G
           

整個環境一共4G,加上JVM堆記憶體1.8G(1792M),已經明顯的超過了4G。

(6.3G + 1.8G)=8.1G > 4G
           

如果按照此計算,應用應用早就被OOM了。

怎麼回事呢?

為了解決這個問題,筆者又思考了好久。如下所示:

Java線程底層實作

JVM的線程在linux上底層是調用NPTL(Native Posix Thread Library)來建立的,一個JVM線程就對應linux的lwp(輕量級程序,也是程序,隻不過共享了mm_struct,用來實作線程),一個thread.start就相當于do_fork了一把。

其中,我們在JVM啟動時候設定了-Xss=512K(即線程棧大小),這512K中然後有8K是必須使用的,這8K是由程序的核心棧和thread_info公用的,放在兩塊連續的實體頁框上。如下圖所示:

實戰記一次JVM堆外記憶體洩露Bug的查找

衆所周知,一個程序(包括lwp)包括核心棧和使用者棧,核心棧+thread_info用了8K,那麼使用者态的棧可用記憶體就是:

512K-8K=504K
           

如下圖所示:

實戰記一次JVM堆外記憶體洩露Bug的查找

Linux實際實體記憶體映射

事實上linux對實體記憶體的使用非常的摳門,一開始隻是配置設定了虛拟記憶體的線性區,并沒有配置設定實際的實體記憶體,隻有推到最後使用的時候才配置設定具體的實體記憶體,即所謂的請求調頁。如下圖所示:

實戰記一次JVM堆外記憶體洩露Bug的查找

檢視smaps程序記憶體使用資訊

使用如下指令,檢視

cat /proc/[pid]/smaps > smaps.txt
           

實際實體記憶體使用資訊,如下所示:

7fa69a6d1000-7fa69a74f000 rwxp 00000000 00:00 0
Size:                504 kB
Rss:                  92 kB
Pss:                  92 kB
Shared_Clean:          0 kB
Shared_Dirty:          0 kB
Private_Clean:         0 kB
Private_Dirty:        92 kB
Referenced:           92 kB
Anonymous:            92 kB
AnonHugePages:         0 kB
Swap:                  0 kB
KernelPageSize:        4 kB
MMUPageSize:           4 kB

7fa69a7d3000-7fa69a851000 rwxp 00000000 00:00 0
Size:                504 kB
Rss:                 152 kB
Pss:                 152 kB
Shared_Clean:          0 kB
Shared_Dirty:          0 kB
Private_Clean:         0 kB
Private_Dirty:       152 kB
Referenced:          152 kB
Anonymous:           152 kB
AnonHugePages:         0 kB
Swap:                  0 kB
KernelPageSize:        4 kB
MMUPageSize:           4 kB
           

搜尋下504KB,正好是12563個,對了12563個線程,其中Rss表示實際實體記憶體(含共享庫)92KB,Pss表示實際實體記憶體(按比例共享庫)92KB(由于沒有共享庫,是以Rss==Pss),以第一個7fa69a6d1000-7fa69a74f000線性區來看,其映射了92KB的空間,第二個映射了152KB的空間。如下圖所示:

實戰記一次JVM堆外記憶體洩露Bug的查找

挑出符合條件(即size是504K)的幾十組看了下,基本都在92K-152K之間,再加上核心棧8K

(92+152)/2+8K=130K,由于是估算,取整為128K,即反映此應用平均線程棧大小。
           

注意,實際記憶體有波動的原因是由于環境不同,進而走了不同的分支,導緻棧上的增長不同。

重新進行記憶體計算

JVM一開始申請了

-Xmx1792m -Xms1792m
           

即1.8G的堆内記憶體,這裡是即時配置設定,一開始就用實體頁框填充。

12563個線程,每個線程棧平均大小128K,即:

128K * 12563=1570M=1.5G的對外記憶體
           

取個整數128K,就能反映出平均水準。再拿這個128K * 12563 =1570M = 1.5G,加上JVM的1.8G,就已經達到了3.3G,再加上kernel和日志傳輸程序等使用的記憶體數量,确實已經接近了4G,這樣記憶體就對應上了!(注:用于定量記憶體計算的環境是一台記憶體用量将近4G,但還沒OOM的機器)

為什麼在實體機上沒有應用Down機

筆者登入了原來實體機,應用還在跑,發現其同樣有堆外記憶體洩露的現象,其實體記憶體使用已經達到了5個多G!幸好實體機記憶體很大,而且此應用釋出還比較頻繁,是以沒有被OOM。

Dump了實體機上應用的線程,

一共有28737個線程,其中28626個線程等待在CachedBnsClient上。
           

同樣用smaps檢視程序實際記憶體資訊,其平均大小依舊為

128K,因為是同一應用的原因
           

繼續進行實體記憶體計算

1.8+(28737 * 128k)/1024K =(3.6+1.8)=5.4G
           

進一步驗證了我們的推理。

這麼多線程應用為什麼沒有卡頓

因為基本所有的線程都睡眠在

Thread.sleep(60 * 1000);//一次睡眠60s
           

上。是以僅僅占用了記憶體,實際占用的CPU時間很少。

總結

查找Bug的時候,現場資訊越多越好,同時定位Bug必須要有實質性的證據。例如記憶體洩露就要用你推測出的模型進行定量分析。在定量和實際對不上的時候,深挖下去,你會發現不一樣的風景!

為幫助開發者們提升面試技能、有機會入職BATJ等大廠公司,特别制作了這個專輯——這一次整體放出。

大緻内容包括了: Java 集合、JVM、多線程、并發程式設計、設計模式、Spring全家桶、Java、MyBatis、ZooKeeper、Dubbo、Elasticsearch、Memcached、MongoDB、Redis、MySQL、RabbitMQ、Kafka、Linux、Netty、Tomcat等大廠面試題等、等技術棧!

實戰記一次JVM堆外記憶體洩露Bug的查找

歡迎大家關注公衆号【Java爛豬皮】,回複【666】,擷取以上最新Java後端架構VIP學習資料以及視訊學習教程,然後一起學習,一文在手,面試我有。

每一個專欄都是大家非常關心,和非常有價值的話題,如果我的文章對你有所幫助,還請幫忙點贊、好評、轉發一下,你的支援會激勵我輸出更高品質的文章,非常感謝!

實戰記一次JVM堆外記憶體洩露Bug的查找

繼續閱讀