记一次JVM老生代增长过快问题排查

28 Oct 2017

临近双11,大家都忙着发布各种优化版本,程序猿手起键落,满意的敲下最后一个回车键,心里想着这就是双十一最终版了,然而不知道等着他的是下一个双十一最终版……

版本上线后,观察了几天,程序猿发现一个异常现象,之前一直非常平稳的JVM老生代突然在上线后以有了明显的增长,而且是持续的增长。于是开始了这次老生代过快增长的问题排查……

揪出导致老生代快速增长的对象分析内存对象

先得找个好用的工具,淘宝开源的TBJMap对jmap做了个增强版,可以将JVM新老生代的各个对象实例个数和大小的Histgram打印出来。

想看出老生代里是什么对象在不断增长,用TBJMap的改版(同事做的优化版)分别dump两天的老生代对象实例出来。 第一天的dump:

#num	#all count/bytes    #old count/bytes   #Class description
-----------------------------------------------------------------------------------
1:	       102/    1k        102/    1k   $Proxy22
2:	      7073/  283k       6403/  258k   boolean[]
3:	    200073/  157m      85594/  135m   byte[]
4:	       493/   26k        137/    4k   byte[][]
...
60:	    365800/   22m     357186/   21m   com.mysql.jdbc.ConnectionPropertiesImpl$BooleanConnectionProperty
61:	     86800/    5m      84756/    5m   com.mysql.jdbc.ConnectionPropertiesImpl$IntegerConnectionProperty
62:	      3100/  193k       3027/  189k   com.mysql.jdbc.ConnectionPropertiesImpl$LongConnectionProperty
63:	      9300/  653k       9081/  638k   com.mysql.jdbc.ConnectionPropertiesImpl$MemorySizeConnectionProperty
64:	    127100/    7m     124107/    7m   com.mysql.jdbc.ConnectionPropertiesImpl$StringConnectionProperty
65:	      3100/    3m       3027/    3m   com.mysql.jdbc.JDBC4Connection
66:	      3126/   97k       3027/   94k   com.mysql.jdbc.JDBC4DatabaseMetaData
67:	       990/  239k        924/  223k   com.mysql.jdbc.MysqlIO
68:	      2927/   68k       2854/   66k   com.mysql.jdbc.NetworkResources
69:	      3100/   96k       3027/   94k com.mysql.jdbc.NonRegisteringDriver$ConnectionPhantomReference

从这份dump中发现JDBC4Connection这个类有些奇怪,程序里是用了连接池的,但这里的连接实例个数却有3027个,远远超过连接池配置的最大连接数,带着这个疑问,再看看第二天的dump:

#num	#all count/bytes    #old count/bytes   #Class description
-----------------------------------------------------------------------------------
1:	       102/    1k        102/    1k   $Proxy22
2:	      8407/  336k       8017/  321k   boolean[]
3:	    196962/  174m      88444/  153m   byte[]
4:	       512/   27k        190/    5k   byte[][]
...
60:	    462088/   28m     452412/   27m   com.mysql.jdbc.ConnectionPropertiesImpl$BooleanConnectionProperty
61:	    109648/    6m     107352/    6m   com.mysql.jdbc.ConnectionPropertiesImpl$IntegerConnectionProperty
62:	      3916/  244k       3834/  239k   com.mysql.jdbc.ConnectionPropertiesImpl$LongConnectionProperty
63:	     11748/  826k      11502/  808k   com.mysql.jdbc.ConnectionPropertiesImpl$MemorySizeConnectionProperty
64:	    160556/    9m     157194/    9m   com.mysql.jdbc.ConnectionPropertiesImpl$StringConnectionProperty
65:	      3916/    4m       3834/    4m   com.mysql.jdbc.JDBC4Connection
66:	      3933/  122k       3834/  119k   com.mysql.jdbc.JDBC4DatabaseMetaData
67:	      1266/  306k       1200/  290k   com.mysql.jdbc.MysqlIO
68:	      3697/   86k       3615/   84k   com.mysql.jdbc.NetworkResources
69:	      3916/  122k       3834/  119k   com.mysql.jdbc.NonRegisteringDriver$ConnectionPhantomReference

两份dump对比,不难发现老生代里明显增长的对象就是这个JDBC4Connection(其他几个都是和这个类相关引用的)。 到底是哪里来的这些数据库连接呢? 注:这里采用连接池是c3p0, 版本是c3p0-0.9.5-pre8 紧跟用jmap将整个heap dump下来,通过MAT进行分析,JDBC4Connection这个对象一共有3792个实例,占用了100多M内存。 image

其中一个实例的GC Root Path:image

可见它被两个对象引用,一个是连接池BasicResourcePool的unused成员变量,一个是MySQL JDBC Driver的ConnectionPhantomReference,跟踪到源码中看看:

BasicResourcePool.java

/* all valid, managed resources currently available for checkout */
LinkedList unused = new LinkedList();

可见unused对象是连接池里的正常可用的连接。

NonRegisteringDriver.java

protected static void trackConnection(Connection newConn) {
	ConnectionPhantomReference phantomRef = new ConnectionPhantomReference((ConnectionImpl) newConn, refQueue);
	connectionPhantomRefs.put(phantomRef, phantomRef);
}

这个虚引用是在JDBC Driver在构造connection时用来track这个connection的,在被GC回收前做一些clean up(释放资源)的事情,所以每个connection被构造出来后,都会被track,这是Driver为了防止有资源随着连接回收而未释放的手段。

可见,这个JDBC4Connection实例是堂堂正正的连接池里的连接实例,呆在老生代是理所当然的。

再来看另一个:

image

这个实例除了ConnectionPhantomReference引用外,还有一个也是连接池BasicResourcePool里的对象:formerResources,顾名思义:曾经在连接池里呆过的对象。

再检查其他的JDBC4Connection实例的GC Root Path,大部分都是第二个这种,被formerResources引用到的。

看到这里,基本已经清晰了,这些多出来的连接对象,应该是曾经被连接池里创建出来,用完后被抛弃掉的连接,被放到formerResources,这些对象熬过了几轮YGC,到了老生代,等着被老生代GC回收的”退休”对象。

真相渐渐浮出水面

继续跟进加入formerResources的相关代码:

private void removeResource(Object resc, boolean synchronous){
    ...
    unused.remove(resc);
    destroyResource(resc, synchronous, checked_out);

    addToFormerResources( resc );

    asyncFireResourceRemoved( resc, false, managed.size(), unused.size(), excluded.size() );
  	...
}

private void cullExpired(){
  	...
    if ( shouldExpire( resc ) )
    {
        if ( logger.isLoggable( MLevel.FINER ) )
            logger.log( MLevel.FINER, "Removing expired resource: " + resc + " [" + this + "]");

        target_pool_size = Math.max( min, target_pool_size - 1 ); //expiring a resource resources the target size to match

        removeResource( resc );
    }
  	...
}

public Object checkoutResource( long timeout ){

    Object resc = prelimCheckoutResource( timeout );

...
}

private synchronized Object prelimCheckoutResource( long timeout ){
  	...
    Object  resc = unused.get(0);
  	...
    else if ( shouldExpire( resc ) ){
      removeResource( resc );
      ensureMinResources();
      return prelimCheckoutResource( timeout );
	}
}

重点关注removeResource这个方法,这个是连接池管理连接的一个重要方法,大致浏览了下调用它的地方,注意到cullExpiredcheckoutResource这两处: