记一次"内存泄露"排查过程

问题的发现

今天发现线上一个应用内存占用非常高，但它的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，所以没用的实例都被释放了。

参考文章:

• JVM 优化经验总结