記一次"記憶體洩露"排查過程

talex發表於2019-10-15
原文網址 : https://juejin.im/post/5da579bf6fb9a04e143dbd3c
記憶體洩露

問題的發現

今天發現線上一個應用記憶體佔用非常高，但它的cpu使用率卻很低

使用ps命令，可以看到 程式 19793 佔用了4.9G的記憶體，然而它cpu使用率還不到5%，有問題。

# ps -aux | grep 19793
user     19793  1.6  9.9 23864228 4904664 ?    Sl   Oct03 268:52 
複製程式碼

我判斷這個應用應該是發生了記憶體洩露，開始進行問題定位和排查。

記憶體洩露的排查過程一般如下：

  1. 使用 jmap 檢視哪些物件個數非常多，記憶體佔用多
  2. 分析 dump 檔案和堆佔用情況
  3. 定位具體的類和相關程式碼的呼叫過程，一步一步的查詢問題所在

工具的使用和介紹這裡不贅述了，引用一個博主的文章

問題定位與排查

1. 使用 jmap 檢視堆的使用情況

執行命令 jmap -hive 19793 檢視物件例項的情況，如圖：

記一次"記憶體洩露"排查過程

這裡發現 StandardSession 例項竟然有140萬個。StandardSession 是tomcat的Session的具體實現，難道說Tomcat發生了記憶體洩露了。

2. 瞭解Tomcat Session的實現和回收原理

Tomcat 使用 StandardManager 管理服務的Session，而 StandardSession儲存了每個Session物件的資料。

StandardManager 會定期檢測每個Session例項是否過期，如果過期，則進行回收處理。

這裡直接看原始碼，瞭解 Tomcat 如何 管理 Session 的

// 具體的檢測程式碼在父類 ManagerBase 中
public StandardManager extends ManagerBase {
     // ... 忽略不必要的程式碼
}


public abstract class ManagerBase extends LifecycleMBeanBase implements Manager {
    
    //Session例項都是儲存在這個Map中的，key 值是 sessionId
    protected Map<String, Session> sessions = new ConcurrentHashMap<>();
    
    // 定時執行函式，Tomcat 有一個守護執行緒，會定時的遍歷執行每個容器的 backgroundProcess 函式，
    // 一般需要定時執行的程式碼，都會實現這個函式，讓Tomcat統一呼叫，這樣也方便管理
    public void backgroundProcess() {
        count = (count + 1) % processExpiresFrequency;
        if (count == 0)        
            processExpires();
     }
     
     public void processExpires() {   
        //記錄當前時間
        long timeNow = System.currentTimeMillis();    
        Session sessions[] = findSessions();    
        int expireHere = 0 ;    
      
        //遍歷所有session，檢視是否過期
        for (int i = 0; i < sessions.length; i++) {    
            //判斷session是否過期，這裡可以看出實際判斷是否過期的實現在 session 類中 
            if ( sessions[i]!=null && !sessions[i].isValid() ) {            
                expireHere++;        
            }    
        }    
        long timeEnd = System.currentTimeMillis();    
        processingTime += ( timeEnd - timeNow );}
}

複製程式碼

這裡看看StandardSession的程式碼


// 看看StandardSession 怎麼判斷 session 是否過期的
public class StandardSession implements HttpSession, Session, Serializable {

    //最後活躍時間
    protected volatile long lastAccessedTime = creationTime;

    // 過期時間，-1 為用不過期
    protected volatile int maxInactiveInterval = -1;

    // 記錄該例項是否已做過期處理
    protected volatile boolean isValid = false;

    @Override
    public boolean isValid() {   
        //判斷是否已經做過期處理
        if (!this.isValid) {        
            return false;    
        }

       //這裡開始判斷session是否有過期
       if (maxInactiveInterval > 0) {       
            //getIdleTimeInternal 函式是計算最後一次使用時間到當前的間隔
            int timeIdle = (int) (getIdleTimeInternal() / 1000L);        
            
            //如果時間間隔大於過期時間，進行清除處理
            //具體的清除就不貼了，簡單的說就是執行 manager 的 sessions.remove(obj) 操作，並且做一下其他的處理
            if (timeIdle >= maxInactiveInterval) {            
                expire(true);       
            }    
        }    
        
       return this.isValid;
   }
}
複製程式碼

通過上述的 manager 和 Session 程式碼，可以清晰的知道 Session 過期處理邏輯，那麼是哪裡出現了問題，導致 Session 物件沒有被回收。

3. 看看自己的程式碼是否有問題

一般來說物件沒有被回收，一定是在某個地方被引用了，這裡看看我程式碼中是怎麼用的。實際上我只有在一個攔截器中使用了 session 的操作。

我專案中應用了 session 的程式碼


// 這是攔截器的一個函式，每個請求進來，必須經過攔截器處理，如果某些方面驗證錯誤，則直接返回錯誤資訊給客戶端
public boolean preHandle(HttpServletRequest request, Object handler) throws IOException {
 
     // 獲取該請求的 Session物件
     HttpSession httpSession = request.getSession();
     
     // 獲取請求的引數，並操作 httpSession 
    // 這裡 setMaxInactiveInterval 表示設定該session的過期時間，1800s
     String sessionUin = (String) httpSession.getAttribute("uin");
     httpSession.setAttribute("uin", uin);
     httpSession.setMaxInactiveInterval(1800);
    
    // 其他處理邏輯 ...
    
    return true;
}
複製程式碼

講道理，我的程式碼使用是不可能引起記憶體洩露的，難道我遇到了Tomcat的bug，想想有點興奮，繼續找原因吧。

4. 匯出線上程式的堆疊資訊，檢視StandardSession例項的值

匯出程式的堆疊資訊： jmap -dump:format=b,file=tomcatDump 19793

利用 jhat 看看 StandardSession 例項的狀態

記一次"記憶體洩露"排查過程

這裡可以看到這個 StandardSession 的 isValid = false，說明該例項進行過快取過期處理，

看看它最後一次被訪問的時間 lastAccessedTime: 1570329063605，將時間戳轉換一下，時間為 2019-10-06 10:31:03:605，而當前時間為2019-10-13，這早就過期了呀，怎麼回事呢。

這好像不太對勁啊，在網上看看有沒有其他人遇到過同樣的問題。使用谷歌搜尋，根本沒有發現有這樣情況的人。

我都打算另尋他法了，發現還真的有人跟我遇到一樣的問題了。但是仔細一看，原來是tomcat6的bug，tomcat的開發人員讓他升級到tomcat7就可以了。而專案用的是tomcat9，這個問題早就修復了。

5. 再次檢視專案的堆疊使用情況

第二天，我還是有點不死心，話說問題沒解決怎麼能行。

檢視專案中例項的數量

> jmap -hive 19793
 num     #instances         #bytes  class name
----------------------------------------------
   1:         37494       76896680  [I
   2:         25378       20727448  [B
   3:        171462       19284664  [C
   4:        141175        3388200  java.lang.String
   5:           561        2513408  [Ljava.util.concurrent.ConcurrentHashMap$Node;
   6:         77525        2480800  java.util.HashMap$Node
   7:         38859        2247400  [Ljava.lang.Object;
   8:         20021        1761848  java.lang.reflect.Method
   9:         14842        1651912  java.lang.Class
  10:         51005        1632160  java.util.concurrent.ConcurrentHashMap$Node
  11:         18588        1567464  [Ljava.util.HashMap$Node;
  12:         29526        1181040  java.util.LinkedHashMap$Entry
  13:         13645         764120  java.util.LinkedHashMap
  14:         36894         763928  [Ljava.lang.Class;
  15:         22800         729600  com.mysql.cj.conf.BooleanProperty
  16:         14720         706560  java.util.HashMap
  17:         37818         605088  java.lang.Object
  18:         18016         432384  java.util.ArrayList
複製程式碼

納尼，我的140萬個 StandardSession 例項呢，怎麼全沒了。看看應用的記憶體佔用，還是一樣啊，佔了差不多5GB的空間，不對勁。

看看堆疊使用情況

> jmap -heap 19793

using thread-local object allocation.
Parallel GC with 18 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   
//...省略部分不必要的東西

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 3287285760 (3135.0MB)
   used     = 53116712 (50.656044006347656MB)
   free     = 3234169048 (3084.3439559936523MB)
   1.6158227753220944% used
   
   //...省略部分不必要的東西
   
PS Old Generation
   capacity = 1083703296 (1033.5MB)
   used     = 62036632 (59.162742614746094MB)
   free     = 1021666664 (974.3372573852539MB)
   5.724503397653226% used
複製程式碼

分析下這些資訊：

  • Eden Space: 新生代堆的使用情況

    • capacity :總大小，當前堆的大小為 3.1GB
    • used : 已使用的空間， 當前已使用 50MB
    • free : 空閒的空間 當前空閒了3.08GB
    • 使用率為 1.6%

  • PS Old Generation: 老年代堆的使用情況

    • capacity :總大小，當前堆的大小為 1 GB
    • used : 已使用的空間， 當前已使用 59 MB
    • free : 空閒的空間 當前空閒了 974 MB
    • 使用率為 5.7%

為什麼空閒了這麼多記憶體沒有被釋放，發生了什麼。等等，還有兩個重要引數沒有講

  • Heap Configuration : 堆的配置資訊
    • MinHeapFreeRatio : 堆空間最小空閒比例 ，如果堆的空閒比例小於這個值，JVM將進行擴容處理
    • MaxHeapFreeRatio : 堆空間最大空閒比例， 如果堆的空閒比例超過這個值，JVM將壓縮堆空間
6. 問題定位及解決方法

到這就知道問題所在了，堆的最大空閒比例為100，表示當堆的使用率為0%時，才會對堆記憶體做壓縮，這永遠不會對堆記憶體進行壓縮處理嘛，坑爹呢。

當JVM進行垃圾回收的時候，將不必要的例項清除了，但是由於配置的原因，導致空間不會被壓縮，所以該應用一直佔用很多空間，而且還越用越大。

解決方法就是在執行的時候在執行的時候加上 -XXMinHeapFreeRatio=10 -XX:MaxHeapFreeRatio=60。

7. 一點小擴充

這裡擴充一下專案中兩種Java堆的配置。

  • 穩定的Java堆

-Xms 和 -Xmx 相等，JVM一開始就分配最大的堆記憶體，如此一來就不需要在執行的時候頻繁的擴充堆的記憶體 這個在高吞吐量的專案中是非常實用的。不需要頻繁的擴充堆，也不需要頻繁的進行垃圾回收處理，可以減少垃圾回收的次數和總時間。 -Xms 和 -Xmx 相等時，MinHeapFreeRatio 和 MaxHeapFreeRatio 的配置將無效。（這都不需要動態擴充套件堆大小了，就算配置也用不上）

  • 動盪的Java堆

如果不做處理JVM預設會配置該模式，即 -Xms初始是一個比較小的值，在系統執行時需要更大的堆空間，才會去擴充套件堆的大小，直到 -Xms 等於 -Xmx

總結

到此，這次的“記憶體洩露”事件就結束了，其實也不是記憶體洩露。

一開始問題定位錯了，還以為是Tomcat的原因，還特意的去了解Tomcat 的 Session 管理機制和程式碼實現。還好後來發現了問題所在，沒有在錯誤的方向浪費太多時間，不然把Tomcat的原始碼翻一遍也找不到具體原因。

補充一點，為什麼140萬個StandardSession例項已經做過期處理了，但是沒有釋放呢，這是因為系統記憶體還較為充足，而且這些例項經過多次 minorGC 都轉移到了年老代（專案的Session的有效期為5個小時），如果不進行一次FullGC，是不會整理年老代的資料的。第二天發現例項被清除，這是因為我執行了 jmap -dump 命令，這個會強制的讓JVM執行一次FullGC，所以沒用的例項都被釋放了。

參考文章:

相關文章