项目内存泄露(memory leak)问题解决记录

1 背景

最近在排查东方通(Tongweb)反复多次部署应用异常，总是出现Meatspace内存溢出的问题，最后知道原来在解部署（关闭）项目时，若项目卸载不干净，也就是应用创建的线程无法正常关闭时，会导致整个应用加载的class不能卸载。因此多次部署后无论Metaspace设置多大，总会出现内存溢出问题OutOfMemoryError：Metaspace。

为了解决这个问题，需要排查应用中那些无法正常关闭的线程。下面就是本地排查中发现的内存泄露问题并做相应分析解决。

项目是web.xml类型的，服务器是tomcat8.5.39，日志是tomcat关闭时所产生的。

2 问题一： log4j2的线程不能关闭

2.1 问题日志

警告 [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [xxxx] appears to have started a thread named [Log4j2-TF-10-Scheduled-2] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 sun.misc.Unsafe.park(Native Method)
 java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
 java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
 java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
 java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
 java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
 java.lang.Thread.run(Thread.java:748)

2.2 问题分析

日志里最重要的信息是a thread named [Log4j2-TF-10-Scheduled-2] but has failed to stop it，意思是一个 名叫Log4j2-TF-10-Scheduled-2的线程在程序关闭后不能停止。Scheduled ？Log4j2有什么定时任务呢？

检查log4j2的配置文件（log4j2.xml）可知，在configuration标签有一个配置monitorInterval，它的功能是配置自动扫描的时间间隔，周期性的间隔配置时间后去检测当前log4j2配置文件的变更并重新配置。

应该就是这个配置了，可以测试一下。修改Log4j2自身日志级别配置status改为TRACE，monitorInterval改为10，再去查看应用打印日志。发现有一个Log4j2-TF-5-Scheduled-1线程就是在周期性的间隔10s执行，看名字这个线程和上面无法关闭的线程是同类型的。**

<!--日志级别以及优先级排序: OFF > FATAL > ERROR > WARN > INFO > DEBUG > TRACE > ALL -->
<!--status="WARN" :用于设置log4j2自身内部日志的信息输出级别，默认是OFF-->
<!--monitorInterval="30"  :间隔秒数,自动检测配置文件的变更和重新配置本身-->
<configuration status="TRACE" monitorInterval="10">
...
</configuration>

2022-09-23 11:23:31,896 Log4j2-TF-5-Scheduled-1 TRACE WatchRunnable run triggered.
2022-09-23 11:23:31,896 Log4j2-TF-5-Scheduled-1 TRACE WatchRunnable run ended.
2022-09-23 11:23:41,912 Log4j2-TF-5-Scheduled-1 TRACE WatchRunnable run triggered.
2022-09-23 11:23:41,913 Log4j2-TF-5-Scheduled-1 TRACE WatchRunnable run ended.
2022-09-23 11:23:51,917 Log4j2-TF-5-Scheduled-1 TRACE WatchRunnable run triggered.
2022-09-23 11:23:51,917 Log4j2-TF-5-Scheduled-1 TRACE WatchRunnable run ended.

结论：通过以上分析可知问题根本就是monitorInterval配置后开启的自动监测线程无法关闭造成的。

2.3 问题解决

一般项目运行中并不会修改日志配置，所以将configuration标签里的monitorInterval直接去掉即可。

另外在测试中发现这个monitorInterval并没起作用，后面有机会再研究。

<configuration status="WARN">
...
</configuration>

3 问题二： JDBC驱动无法注销

3.1 问题日志

警告 [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesJdbc The web application [xxxx] registered the JDBC driver [com.microsoft.sqlserver.jdbc.SQLServerDriver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.

3.2 问题分析

这是说JDBC驱动被应用注册了，但是应用关闭时未能注销。为了防止内存泄漏，JDBC驱动程序被Tomcat注销了。查了下说是从6.0.24版开始，Tomcat附带了内存泄漏检测功能，当webapp的/WEB-INF/lib中存在与JDBC 4.0兼容的驱动程序时，该功能会导致这种警告消息，该驱动程序在webapp启动期间使用< x1> API，但在webapp关闭期间不会自动注销自身。

3.2.1 那什么时候注册的呢？

首先要搞清楚何为注册驱动？

查看源码，jdbc驱动类地址都配置在连接池中，连通过连接池来加载驱动类。

 // 连接池是Hikari
  public void setDriverClassName(String driverClassName) {
  ......
        ClassLoader threadContextClassLoader = Thread.currentThread().getContextClassLoader();
        // 记载驱动类
        driverClass = threadContextClassLoader.loadClass(driverClassName);
  ......

这里有个疑问，连接池源码里只看到加载驱动实现类，并没有其他特殊操作。所以再看下驱动实现类源码，发现在JDBC驱动实现类的静态代码块static里，都创建了自身对象并调用DriverManager.registerDriver(jdbc object)进行注册。这里看下sqlserver和达梦（dm）的源码。

  // sqlserver的JDBC实现类SQLServerDriver
  static {
  ...
        try {
            DriverManager.registerDriver(new SQLServerDriver());
        } catch (SQLException var1) {
            var1.printStackTrace();
        }

    }
  // 达梦的JDBC实现类DmDriver
 public static DmDriver n = new DmDriver();
 static {
        try {
            DriverManager.registerDriver(n);
        } catch (Exception var0) {
            DBError.throwRuntimeException("Can not load Driver class dm.jdbc.driver.DmDriver");
        }

        IDGenerator = new AtomicLong(0L);
    }

在往下看源码，发现DriverManager.registerDriver(jdbc object)这行代码实际上是往驱动管理类的静态集合List里添加JDBC驱动的包装对象。这就是真正注册的意思了。

 public class DriverManager {

     //  List of registered JDBC drivers
     private final static CopyOnWriteArrayList<DriverInfo> registeredDrivers = new CopyOnWriteArrayList<>();

     public static synchronized void registerDriver(java.sql.Driver driver)
        throws SQLException {
        registerDriver(driver, null);
     }

     public static synchronized void registerDriver(java.sql.Driver driver,
            DriverAction da)
        throws SQLException {

        /* Register the driver if it has not already been added to our list */
        if(driver != null) {
          // 在这里
            registeredDrivers.addIfAbsent(new DriverInfo(driver, da));
        } else {
            // This is for compatibility with the original DriverManager
            throw new NullPointerException();
        }
        println("registerDriver: " + driver);
     }  
  } 

3.2.2 什么时候注销呢？

JDBC驱动是在连接池创建时注册的，也应该在连接池关闭时去注销，但是查看连接池的close方法源码并没发现此类代码。

3.2.3 结论

本质上就是JDBC驱动在项目启动时加载类并注册后，在应用关闭时也没有注销导致的内存泄露，而tomcat在关闭应用时检测到这一问题后解决并进行警告提示。

3.3 问题解决

既然JDBC驱动没有自动注销，则考虑在应用关闭时手动注销. 这里通过实现servlet的ServletContextListener，在Web应用关闭时进行JDBC的驱动注销。当然我们也可以把其他的一些关闭资源操作也放在这里。

这里主要考虑两个方面：

• tomcat能检测到内存泄露并解决，不代表其他应用服务器可以，所以要在项目里手动控制避免内存泄露。

• 在通过 DriverManager.deregisterDriver(driver)注销驱动时要考虑这个DriverManager类是哪个类加载器加载的（上面源码可看到驱动类共用一个CopyOnWriteArrayList）。若是父类ClassLoader(即servlet容器的类加载器)加载而不是webapp上下文的ClassLoader(例如，它们可能位于容器的lib文件夹中，而不是webapp的文件夹中，因此在整个容器中共享)，取消这些注册将影响可能同一容器内正在使用它们的其他Web应用程序(甚至容器本身)。因此，在注销之前，最好检查每个驱动程序的ClassLoader是否是webapp的ClassLoader。

3.3.1 编写servlet的监听器实现类

import javax.servlet.ServletContextEvent;
import javax.servlet.ServletContextListener;
import java.sql.Driver;
import java.sql.DriverManager;
import java.sql.SQLException;
import java.util.Enumeration;
import java.util.logging.Logger;

public class MyContextListener implements ServletContextListener {

    private static final Logger log = Logger.getLogger(MyContextListener.class.getName());

    @Override
    public void contextInitialized(ServletContextEvent servletContextEvent) {

    }
    @Override
    public void contextDestroyed(ServletContextEvent servletContextEvent) {
        // 关闭JDBC驱动
        Enumeration<Driver> drivers = DriverManager.getDrivers();
        ClassLoader cl = Thread.currentThread().getContextClassLoader();
        while (drivers.hasMoreElements()) {
            Driver driver = drivers.nextElement();
            if (driver.getClass().getClassLoader() == cl) {
                try {
                    DriverManager.deregisterDriver(driver);
                    log.info("Close Jdbc Driver:" + driver);
                } catch (SQLException e) {
                    log.warning("Close Jdbc Driver exception:" + e);
                }
            } else {
                log.info("The JDBC driver " + driver + " not belong to this webapp's ClassLoader");
            }
        }
    }

}

3.3.2 在web.xml里配置监听器

    <listener>
     ...
    </listener>
<!--    资源清理监听器放在所有监听器最后面-->
    <listener>
        <listener-class>com..MyContextListener</listener-class>
    </listener>

4 问题三：ThreadLocal内存泄露

4.1 问题日志

26-Sep-2022 17:26:05.396 严重 [localhost-startStop-2] 
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks 
The web application [xxxx] created a ThreadLocal with key of type 
[com.microsoft.sqlserver.jdbc.ActivityCorrelator$1] 
(value [com.microsoft.sqlserver.jdbc.ActivityCorrelator$1@3632c930]) 
and a value of type [com.microsoft.sqlserver.jdbc.ActivityId] 
(value [99e80fd2-702d-42f9-a30f-6f4852617cd9-0]) 
but failed to remove it when the web application was stopped. 
Threads are going to be renewed over time to try and avoid a probable memory leak.

26-Sep-2022 17:26:05.406 严重 [localhost-startStop-2]
 org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks 
 The web application [xxxx] created a ThreadLocal with key of type [java.lang.ThreadLocal] 
 (value [java.lang.ThreadLocal@7c53abca])
 and a value of type [com....web.CActionWrapper] 
 (value [com....web.CActionWrapper@7fa5fb7f]) 
 but failed to remove it when the web application was stopped. 
 Threads are going to be renewed over time to try and avoid a probable memory leak.

4.2 问题分析

上面两个问题都是使用ThreadLocal所产生的内存泄露问题。

第一个应该是sqlserver驱动的本身问题，别的数据库也没有这种问题，换新的驱动包应该可以解决，所以不做讨论。

第二个可以理解为每个request请求相关数据都会产生此对象，并放到static ThreadLocal里方便获取，因为是静态的，一直存在ThreadLocal的强引用，所以ThreadLocal也就不会被回收，也就能保证任何时候都能根据ThreadLocal的弱引用访问到Entry的value值，然后remove它，防止内存泄露。事实上，在响应后会调用ThreadLocal的remove方法进行清除。

正常来说应用停止时，所有请求线程也应该结束了，ThreadLocal相关的ThreadLocalMap也应该被回收了才是。这里还出现这种问题，只能理解为某些请求线程在应用停止后还未结束，此时ThreadLocal的静态强引用导致无法回收ThreadLocalMap中的value了。

4.3 问题解决

在ThreadLocalMap 中的set/get/remove方法中，会对key为null（也即是ThreadLocal为null）进行判断，如果为 null 的话，那么会把 value 置为 null 的。这就很好的避免内存泄露。

利用上述特性把threadLocal静态变量置null，这意味着所有线程中ThreadLocalMap中key都为空，相关Entry为（null,value)，这时很容易触发set/get/remove方法使得Entry中value也为 null，变为（null,null)。然后再主动gc回收value对象。

    public  static  void clearForStop(){
        threadLocal = null;
        System.gc();
    }

public class MyContextListener implements ServletContextListener {
    private static final Logger log = Logger.getLogger(MyContextListener.class.getName());
    @Override
    public void contextDestroyed(ServletContextEvent servletContextEvent) {
        // 关闭JDBC驱动
          ...
        // 清除threadLocal内存泄露
        xxx.clearForStop();
    }

}

5 总结

后面若有其他发现会继续补充！ 有所不足指出，希望各位大佬，多多指正。