2. 程式人生 > >解Bug之路——記一次JVM堆外記憶體洩露Bug的查詢

解Bug之路——記一次JVM堆外記憶體洩露Bug的查詢

阿新 • • 發佈：2019-01-08

前言

JVM的堆外記憶體洩露的定位一直是個比較棘手的問題。此次的Bug查詢從堆內記憶體的洩露反推出堆外記憶體，同時對實體記憶體的使用做了定量的分析，從而實錘了Bug的源頭。筆者將此Bug分析的過程寫成部落格，以饗讀者。
由於實體記憶體定量分析部分用到了linux kernel虛擬記憶體管理的知識，讀者如果有興趣瞭解請看ulk3(《深入理解linux核心第三版》)

記憶體洩露Bug現場

一個線上穩定運行了三年的系統，從物理機遷移到docker環境後，運行了一段時間，突然被監控系統發出了某些例項不可用的報警。所幸有負載均衡，可以自動下掉節點，如下圖所示: gc_local
登入到對應機器上後，發現由於記憶體佔用太大，觸發OOM，然後被linux系統本身給kill了。

應急措施

緊急在出問題的例項上再次啟動應用，啟動後，記憶體佔用正常，一切Okay。

奇怪現象

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

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

檢視作業系統層面的監控，發現記憶體佔用情況如下圖所示: gc_upper
上圖藍色的線表示總的記憶體使用量，發現一直漲到了4G後，超出了系統限制。
很明顯，有堆外記憶體洩露了。

查詢線索

gc日誌

一般出現記憶體洩露，筆者立馬想到的就是檢視當時的gc日誌。
本身應用所採用框架會定時打印出對應的gc日誌，遂檢視，發現gc日誌一切正常。對應日誌如下: gc_log


查看了當天的所有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檔案進行分析，堆的使用情況如下圖所示: gc_heap_dump
一共用了200多M，和之前gc檔案打印出來的170M相差不大，遠遠沒有到4G的程度。
不得不說MAT是個非常好用的工具，它可以提示你可能記憶體洩露的點: gc_cached_bns_client
這個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程式碼的時候遺漏掉了一個關鍵的點!

    publicCachedBnsClient(BnsClient client){
        super();
        this.backendClient = client;
        new Thread() {
            @Override
            publicvoidrun(){
                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公用的，放在兩塊連續的物理頁框上。如下圖所示:
gc_thread_task

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

512K-8K=504K

如下圖所示:
gc_kernel_user

Linux實際實體記憶體對映

事實上linux對實體記憶體的使用非常的摳門，一開始只是分配了虛擬記憶體的線性區，並沒有分配實際的實體記憶體，只有推到最後使用的時候才分配具體的實體記憶體，即所謂的請求調頁。如下圖所示:
gc_do_page_fault

檢視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的空間。如下圖所示:
gc_mem
挑出符合條件（即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必須要有實質性的證據。例如記憶體洩露就要用你推測出的模型進行定量分析。在定量和實際對不上的時候，深挖下去，你會發現不一樣的風景!

我有一個微信公眾號，經常會分享一些Java技術相關的乾貨；如果你喜歡我的分享，可以用微信搜尋“Java團長”或者“javatuanzhang”關注。

相關推薦

解Bug之路——記一次JVM堆外記憶體洩露Bug的查詢

前言JVM的堆外記憶體洩露的定位一直是個比較棘手的問題。此次的Bug查詢從堆內記憶體的洩露反推出堆外記憶體，同時對實體記憶體的使用做了定量的分析，從而實錘了Bug的源頭。筆者將此Bug分析的過程寫成部落格，以饗讀者。由於實體記憶體定量分析部分用到了linux kernel虛擬

解Bug之路-記一次JVM堆外記憶體洩露Bug的查詢

# 解Bug之路-記一次JVM堆外記憶體洩露Bug的查詢 ## 前言 JVM的堆外記憶體洩露的定位一直是個比較棘手的問題。此次的Bug查詢從堆內記憶體的洩露反推出堆外記憶體，同時對實體記憶體的使用做了定量的分析，從而實錘了Bug的源頭。筆者將此Bug分析的過程寫成部落格，以饗讀者。 由於實體記憶體定量分

解Bug之路-記一次中介軟體導致的慢SQL排查過程

解Bug之路-記一次中介軟體導致的慢SQL排查過程 前言 最近發現線上出現一個奇葩的問題，這問題讓筆者定位了好長時間，期間排查問題的過程還是挺有意思的，正好部落格也好久不更新了，就以此為素材寫出了本篇文章。 Bug現場 我們的分庫分表中介軟體在經過一年的沉澱之後，已經到了比較穩定的階段。而且經過線上壓

解Bug之路-記一次中間件導致的慢SQL排查過程

有一個 bug 第一條 builder mstr 引入 i++ 原來 中間 解Bug之路-記一次中間件導致的慢SQL排查過程 前言 最近發現線上出現一個奇葩的問題，這問題讓筆者定位了好長時間，期間排查問題的過程還是挺有意思的，正好博客也好久不更新了，就以此為素材寫出了本篇文

解Bug之路-記一次儲存故障的排查過程

# 解Bug之路-記一次儲存故障的排查過程 高可用真是一絲細節都不得馬虎。平時跑的好好的系統，在相應硬體出現故障時就會引發出潛在的Bug。偏偏這些故障在應用層的表現稀奇古怪，很難讓人聯想到是硬體出了問題，特別是偶發性出現的問題更難排查。今天，筆者就給大家帶來一個儲存偶發性故障的排查過程。 ## Bug現場 我

解Bug之路-記一次呼叫外網服務概率性失敗問題的排查

# 解Bug之路-記一次呼叫外網服務概率性失敗問題的排查 ## 前言 和外部聯調一直是令人困擾的問題，尤其是一些基礎環境配置導致的問題。筆者在一次偶然情況下解決了一個呼叫外網服務概率性失敗的問題。在此將排查過程發出來，希望讀者遇到此問題的時候，能夠知道如何入手。 ## 起因 筆者的新系統上線，需要PE執行操作

解Bug之路-記一次對端機器宕機後的tcp行為

# 解Bug之路-記一次對端機器宕機後的tcp行為 ## 前言 機器一般過質保之後，就會因為各種各樣的問題而宕機。而這一次的宕機，讓筆者觀察到了平常觀察不到的tcp在對端宕機情況下的行為。經過詳細跟蹤分析原因之後，發現可以通過調整核心tcp引數來減少宕機造成的影響。 ## Bug現場 筆者所在的公司用某個中介

解Bug之路-記一次線上請求偶爾變慢的排查

# 解Bug之路-記一次線上請求偶爾變慢的排查 ## 前言 最近解決了個比較棘手的問題，由於排查過程挺有意思，於是就以此為素材寫出了本篇文章。 ## Bug現場 這是一個偶發的效能問題。在每天幾百萬比交易請求中，平均耗時大約為300ms，但總有那麼100多筆會超過1s，讓我們業務耗時監控的99.99線變得很尷

今咱們來聊聊JVM 堆外記憶體洩露的BUG是如何查詢的

前言 JVM的堆外記憶體洩露的定位一直是個比較棘手的問題。此次的Bug查詢從堆內記憶體的洩露反推出堆外記憶體，同時對實體記憶體的使用做了定量的分析，從而實錘了Bug的源頭。筆者將此Bug分析的過程寫成部落格，以饗讀者。 由於實體記憶體定量分析部分用到了lin

JVM成長之路,記錄一次記憶體溢位導致頻繁FGC的問題排查及解決

  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT    LGCC                 GCC  0.00  18.29  97.31  50.26  97.42  95.25    

記一次JVM Metaspace溢出排查

jvm參數 oom task visualvm map 排除 創建 thread 類裝載 多圖預警！ 環境：系統測試(Windows Server/JRE8/tomcat7) 現象：應用運行幾天後，出現訪問超時，服務器cpu利用率居高不下 問題日誌：OutOfMemory

記一次網頁超時登錄的Bug

首頁 size blog 登錄 style 評價 員工 bsp 返回 前幾天，在做全公司的員工測評工作，在一個頁面彈出導入頁面，並導入所有評價記錄，然後關閉掉這個導入頁面，最後返回當前頁面，返回時刷新當前頁面。 在返回的時候，就出現了“頁面超時登錄”

【BUG記錄】記一次遊戲越來越卡的BUG

U3D的MOBA專案，測試過程中，10分鐘以後，遊戲幀率開始緩慢下降，約3-5分鐘後，由60幀下降到小於10幀，編輯器模式。 開啟profiler，看到CPU佔用非常高，每幀都有24K的GC, 時間佔用曲線上看是script大量佔用CPU時間。 第一印象，應該是洩漏造成的。定位辦法，profil

記一次 JVM 原始碼分析(3.記憶體管理與GC)

簡介 miniJVM 的記憶體管理的實現較為簡單 記憶體分配使用了開源的 ltalloc 庫 GC就是經典的 Mark-Sweep GC 物件分配 物件分配要關注的就兩個過程 New 一個 Java 物件的過程 記憶體塊在堆上分配的過程 物件在 JVM

記一次 JVM 原始碼分析(4.直譯器與方法執行)

簡介 miniJVM 作為一個 mini 的 Java VM，實現了 Switch 直譯器，並不支援主流 JVM 的 JIT 或者更為複雜的 AOT。但這樣對於我們瞭解位元組碼的執行已經足夠了。 位元組碼指令 基於堆疊 位元組碼指令類似於彙編指令，但是不同的是：

記一次 JVM 原始碼分析(5.異常處理)

異常列印 Java 如果發生異常，通常會呼叫 Throwable.printStackTrace 去列印堆疊資訊。 堆疊資訊包括完整類名，方法名，java 檔名，行號 而這樣的資訊根據發生 Crash 執行緒所經歷的n個方法會打印出n行。 整個過程被稱為棧回朔

記一次MYSQL建表失敗得bug（暫未解決！，求助）

CREATE TABLE `SUIT` ( `id` INTEGER(11) NOT NULL AUTO_INCREMENT, `acId` INTEGER(11) NULL COMMENT '活動ID', `name` VARCHAR(64) NULL COMMENT '套裝名稱', `dis

linux程序和執行緒排查 · 記一次JVM CPU高負載的排查辦法

前言通過本文，你將學會：1、linux上程序及程序中執行緒排查的基本方法，如檢視程序中的執行緒數此文中的執行緒一般指輕量級程序。檢視所有程序資訊 top -H 加上-H這個選項啟動top，top一行顯示一個執行緒（指的是（輕量級）程序？ ）。否則，它一行顯示一個程序。先輸入

記一次排查mbstowcs誤用引發的bug

問題程式碼如下： #define MAX_LINE_LEN (10240*2) char tieziLine[MAX_LINE_LEN]; wchar_t oneTieziLine_wchar[MAX_LINE_LEN];

記一次require＋閉包的bug檢查

今天的你，寫bug了嗎？ 唉什麼都不想說，只怪自己太蠢。閉包和引用，兩個最基礎的知識，結合到了一起，卻忘得一乾二淨，謹以此文，來記錄下這個已經被我K.O的bug，願來生路上，你不再出現。 情況是這樣的，有個函式一個網路請求加處理步驟，結構大概是這樣