当前使用的Spring JDBC版本是5.0.0.RC1HikariCP版本是3.1.0。

今天测试同学反馈在前端页面点击次数多了,就报500错误,数据显示不出来。于是我在后台服务日志中观察发现HikariCP连接池报如下的错误:

getDataByWorkSheetId method Exception:HikariPool-2 - Connection is not available, request timed out after 30000ms.

接着开始FQ搜谷歌,大致要从两方面进行解决:

一、服务端:

1、给业务逻辑层相应的方法加上@Transactional注解,以便启用Spring的事务管理功能,在Spring提交事务之后,自动进行连接资源的释放

2、调整HikariCP连接池的连接参数,比如调整连接池大小以及时间参数

二、数据库端:

调整MySQL数据库的参数。这个参数表示不活动的(noninteractive connection)连接被MySQL服务器关闭之前等待的秒数,默认值是28800秒,换算成小时是8小时。当有线程使用连接时,它会重新被初始化。经过观察发现,当有线程使用akp_test数据库的连接时,相应连接的wait_timeout会清零,然后重新开始计时,直到达到wait_timeout的最大值28800秒。也就是说,不活动的连接如果没有访问,会在达到8小时的空闲时间后被MySQL数据库关闭。

搜索到这个解决办法是因为我用show processlist命令查询了当前操作MySQL数据库的所有运行着的线程,发现操作akp_test数据库的好多连接线程都处于Sleep状态(具体见截图中的Command栏),这种状态表示等待客户端发送操作请求,并且随着时间的推移,Time一栏的时间数值也在逐渐变大,重启连接数据库的应用后这种情况消失,随着访问的增多又逐渐出现了这种现象。Time一栏的时间数值也呈降序排列,此时的访问量并不高,说明每次访问数据库建立的连接可能没有被关闭,导致连接池饱和,出现连接请求超时的问题。

排查过程

经过思考之后,大致可以断定问题出现在访问数据库的方法上,应该是应用操作数据库后连接没有释放引起的连接泄露问题。排查过程如下:

找出访问数据库的方法

我首先尝试了从服务端解决,也就是给业务逻辑层的方法增加@Transactional注解和调整HikariCP连接池的连接参数,都没有效果。最后开始着手从业务逻辑层的getDataByWorkSheetId方法入手查找代码上的问题。getDataByWorkSheetId方法的作用是根据workSheetId去查询相应的业务数据信息,操作数据库用的Spring JDBCJdbcTemplate类,在getDataByWorkSheetId方法中,分别使用了JdbcTemplate类的两个方法:

  • queryForList(String sql):根据相应的sql语句查询数据,返回一个数据集合

  • getDataSource.getConnection.getMetaData.getColumns(String catalog, String schemaPattern,String tableNamePattern, String columnNamePattern):该方法调用链比较长,但调用逻辑清晰,首先是通过getConnection方法获取数据库连接,然后使用getMetaData获取数据库元数据信息,最后调用getColumns获取tableNamePattern对应的数据库表的信息

于是我开始debug两个方法的实现,找出是哪一个方法没有关闭数据库连接。

访问数据库的方法实现

queryForList方法实现

首先看看JdbcTemplate类的queryForList方法实现,该方法最终调用的是JdbcTemplate类的query(final String sql, final ResultSetExtractor<T> rse)方法和execute(StatementCallback<T> action)方法,两个方法实现代码如下,注意关闭数据库连接部分:

1、query(final String sql, final ResultSetExtractor<T> rse):

public 
T query(final String sql, final ResultSetExtractor
rse) throws DataAccessException { Assert.notNull(sql, "SQL must not be null"); Assert.notNull(rse, "ResultSetExtractor must not be null"); if (logger.isDebugEnabled()) { logger.debug("Executing SQL query [" + sql + "]"); } class QueryStatementCallback implements StatementCallback
, SqlProvider { @Override public T doInStatement(Statement stmt) throws SQLException { ResultSet rs = null; try { rs = stmt.executeQuery(sql); return rse.extractData(rs); } finally { // 关闭ResultSet对象 JdbcUtils.closeResultSet(rs); } } @Override public String getSql() { return sql; } } return execute(new QueryStatementCallback()); }

2、execute(StatementCallback<T> action):

public 
T execute(StatementCallback
action) throws DataAccessException { Assert.notNull(action, "Callback object must not be null"); Connection con = DataSourceUtils.getConnection(getDataSource()); Statement stmt = null; try { stmt = con.createStatement(); applyStatementSettings(stmt); T result = action.doInStatement(stmt); handleWarnings(stmt); return result; } catch (SQLException ex) { // 发生异常时关闭Statement对象和Connection对象 // Release Connection early, to avoid potential connection pool deadlock // in the case when the exception translator hasn't been initialized yet. JdbcUtils.closeStatement(stmt); stmt = null; DataSourceUtils.releaseConnection(con, getDataSource()); con = null; throw getExceptionTranslator().translate("StatementCallback", getSql(action), ex); } finally { // 关闭Statement对象 JdbcUtils.closeStatement(stmt); // 关闭Connection对象 DataSourceUtils.releaseConnection(con, getDataSource()); } }

从以上代码片段可以看出,queryForList方法在操作数据库完成后,依次关闭了ResultSet对象、Statement对象和Connection对象。

getColumns方法实现

getColumns方法是java.sql.DatabaseMetaData接口的一个方法,该接口主要是用来定义获取数据库信息应有的方法。该接口根据不同的数据库驱动有不同的实现类,部分实现类如下:

由于我当前使用的是MySQL数据库,因此它的实现类是com.mysql.jdbc.JDBC4DatabaseMetaData类,这个类的getColumns方法最终是调用的它的父类com.mysql.jdbc.DatabaseMetaDatagetColumns方法:

public java.sql.ResultSet getColumns(final String catalog, final String schemaPattern, final String tableNamePattern, String columnNamePattern)            throws SQLException {        if (columnNamePattern == null) {            if (this.conn.getNullNamePatternMatchesAll()) {                columnNamePattern = "%";            } else {                throw SQLError.createSQLException("Column name pattern can not be NULL or empty.", SQLError.SQL_STATE_ILLEGAL_ARGUMENT,                        getExceptionInterceptor());            }        }        final String colPattern = columnNamePattern;        Field[] fields = createColumnsFields();        final ArrayList
rows = new ArrayList
(); final Statement stmt = this.conn.getMetadataSafeStatement(); try { new IterateBlock
(getCatalogIterator(catalog)) { @Override void forEach(String catalogStr) throws SQLException { ArrayList
tableNameList = new ArrayList
(); if (tableNamePattern == null) { // Select from all tables java.sql.ResultSet tables = null; try { tables = getTables(catalogStr, schemaPattern, "%", new String[0]); while (tables.next()) { String tableNameFromList = tables.getString("TABLE_NAME"); tableNameList.add(tableNameFromList); } } finally { if (tables != null) { try { tables.close(); } catch (Exception sqlEx) { AssertionFailedException.shouldNotHappen(sqlEx); } tables = null; } } } else { java.sql.ResultSet tables = null; try { tables = getTables(catalogStr, schemaPattern, tableNamePattern, new String[0]); while (tables.next()) { String tableNameFromList = tables.getString("TABLE_NAME"); tableNameList.add(tableNameFromList); } } finally { if (tables != null) { try { tables.close(); } catch (SQLException sqlEx) { AssertionFailedException.shouldNotHappen(sqlEx); } tables = null; } } } for (String tableName : tableNameList) { ResultSet results = null; try { StringBuilder queryBuf = new StringBuilder("SHOW "); if (DatabaseMetaData.this.conn.versionMeetsMinimum(4, 1, 0)) { queryBuf.append("FULL "); } queryBuf.append("COLUMNS FROM "); queryBuf.append(StringUtils.quoteIdentifier(tableName, DatabaseMetaData.this.quotedId, DatabaseMetaData.this.conn.getPedantic())); queryBuf.append(" FROM "); queryBuf.append(StringUtils.quoteIdentifier(catalogStr, DatabaseMetaData.this.quotedId, DatabaseMetaData.this.conn.getPedantic())); queryBuf.append(" LIKE "); queryBuf.append(StringUtils.quoteIdentifier(colPattern, "'", true)); // Return correct ordinals if column name pattern is not '%' // Currently, MySQL doesn't show enough data to do this, so we do it the 'hard' way...Once _SYSTEM tables are in, this should be // much easier boolean fixUpOrdinalsRequired = false; Map
ordinalFixUpMap = null; if (!colPattern.equals("%")) { fixUpOrdinalsRequired = true; StringBuilder fullColumnQueryBuf = new StringBuilder("SHOW "); if (DatabaseMetaData.this.conn.versionMeetsMinimum(4, 1, 0)) { fullColumnQueryBuf.append("FULL "); } fullColumnQueryBuf.append("COLUMNS FROM "); fullColumnQueryBuf.append( StringUtils.quoteIdentifier(tableName, DatabaseMetaData.this.quotedId, DatabaseMetaData.this.conn.getPedantic())); fullColumnQueryBuf.append(" FROM "); fullColumnQueryBuf.append( StringUtils.quoteIdentifier(catalogStr, DatabaseMetaData.this.quotedId, DatabaseMetaData.this.conn.getPedantic())); results = stmt.executeQuery(fullColumnQueryBuf.toString()); ordinalFixUpMap = new HashMap
(); int fullOrdinalPos = 1; while (results.next()) { String fullOrdColName = results.getString("Field"); ordinalFixUpMap.put(fullOrdColName, Integer.valueOf(fullOrdinalPos++)); } } results = stmt.executeQuery(queryBuf.toString()); int ordPos = 1; while (results.next()) { byte[][] rowVal = new byte[24][]; rowVal[0] = s2b(catalogStr); // TABLE_CAT rowVal[1] = null; // TABLE_SCHEM (No schemas // in MySQL) rowVal[2] = s2b(tableName); // TABLE_NAME rowVal[3] = results.getBytes("Field"); TypeDescriptor typeDesc = new TypeDescriptor(results.getString("Type"), results.getString("Null")); rowVal[4] = Short.toString(typeDesc.dataType).getBytes(); // DATA_TYPE (jdbc) rowVal[5] = s2b(typeDesc.typeName); // TYPE_NAME // (native) if (typeDesc.columnSize == null) { rowVal[6] = null; } else { String collation = results.getString("Collation"); int mbminlen = 1; if (collation != null && ("TEXT".equals(typeDesc.typeName) || "TINYTEXT".equals(typeDesc.typeName) || "MEDIUMTEXT".equals(typeDesc.typeName))) { if (collation.indexOf("ucs2") > -1 || collation.indexOf("utf16") > -1) { mbminlen = 2; } else if (collation.indexOf("utf32") > -1) { mbminlen = 4; } } rowVal[6] = mbminlen == 1 ? s2b(typeDesc.columnSize.toString()) : s2b(((Integer) (typeDesc.columnSize / mbminlen)).toString()); } rowVal[7] = s2b(Integer.toString(typeDesc.bufferLength)); rowVal[8] = typeDesc.decimalDigits == null ? null : s2b(typeDesc.decimalDigits.toString()); rowVal[9] = s2b(Integer.toString(typeDesc.numPrecRadix)); rowVal[10] = s2b(Integer.toString(typeDesc.nullability)); // // Doesn't always have this field, depending on version // // // REMARK column // try { if (DatabaseMetaData.this.conn.versionMeetsMinimum(4, 1, 0)) { rowVal[11] = results.getBytes("Comment"); } else { rowVal[11] = results.getBytes("Extra"); } } catch (Exception E) { rowVal[11] = new byte[0]; } // COLUMN_DEF rowVal[12] = results.getBytes("Default"); rowVal[13] = new byte[] { (byte) '0' }; // SQL_DATA_TYPE rowVal[14] = new byte[] { (byte) '0' }; // SQL_DATE_TIME_SUB if (StringUtils.indexOfIgnoreCase(typeDesc.typeName, "CHAR") != -1 || StringUtils.indexOfIgnoreCase(typeDesc.typeName, "BLOB") != -1 || StringUtils.indexOfIgnoreCase(typeDesc.typeName, "TEXT") != -1 || StringUtils.indexOfIgnoreCase(typeDesc.typeName, "BINARY") != -1) { rowVal[15] = rowVal[6]; // CHAR_OCTET_LENGTH } else { rowVal[15] = null; } // ORDINAL_POSITION if (!fixUpOrdinalsRequired) { rowVal[16] = Integer.toString(ordPos++).getBytes(); } else { String origColName = results.getString("Field"); Integer realOrdinal = ordinalFixUpMap.get(origColName); if (realOrdinal != null) { rowVal[16] = realOrdinal.toString().getBytes(); } else { throw SQLError.createSQLException("Can not find column in full column list to determine true ordinal position.", SQLError.SQL_STATE_GENERAL_ERROR, getExceptionInterceptor()); } } rowVal[17] = s2b(typeDesc.isNullable); // We don't support REF or DISTINCT types rowVal[18] = null; rowVal[19] = null; rowVal[20] = null; rowVal[21] = null; rowVal[22] = s2b(""); String extra = results.getString("Extra"); if (extra != null) { rowVal[22] = s2b(StringUtils.indexOfIgnoreCase(extra, "auto_increment") != -1 ? "YES" : "NO"); rowVal[23] = s2b(StringUtils.indexOfIgnoreCase(extra, "generated") != -1 ? "YES" : "NO"); } rows.add(new ByteArrayRow(rowVal, getExceptionInterceptor())); } } finally { if (results != null) { try { results.close(); } catch (Exception ex) { } results = null; } } } } }.doForAll(); } finally { if (stmt != null) { stmt.close(); } } java.sql.ResultSet results = buildResultSet(fields, rows); return results; }

通过代码中results.close()stmt.close()的调用可以看出,该方法只关闭了ResultSet对象和Statement对象,而没有关闭Connection对象。最终在我们调用方法的时候导致了连接泄露,因此我对getColumns方法进行了二次封装:

/**    * 获取列信息    *    * @param id        数据源ID    * @param tableName 表名    * @return ResultSet对象    */  def getColumns(id: Int, tableName: String): ResultSet = {    var connection: Connection = null    var resultSet: ResultSet = null    try {      connection = getJdbcTemplate(id).getDataSource.getConnection      resultSet = connection.getMetaData.getColumns(null, null, tableName, null)    } catch {      case e: Exception => log.error(s"GetColumns exception: ${e.getMessage}, id: $id, tableName: $tableName")    } finally {      // 关闭连接      if (connection != null && !connection.isClosed) {        connection.close()      }    }    resultSet  }

封装后的方法对获取的数据库连接使用完毕后执行了关闭操作,经测试,连接泄露问题得以解决。

总结

这次连接泄露问题的产生主要是由于没有关闭数据库连接导致,解决过程大致按先后次序可以总结如下:

1、首先使用show processlist命令查询当前操作MySQL数据库所有运行着的线程,并查看结果集中Command栏和Time栏的数据。如果Command栏中大多数线程的状态是Sleep,并且Time栏的数值不断在增大,并且呈降序排序,说明连接没有被复用,而且访问数据库的应用程序一直在创建新连接。这说明已经产生了连接泄露问题

2、看看方法有没有@Transactiona注解或者使用XML配置方式进行事务管理,或者出问题的方法中有没有主动创建连接未关闭的情况。使用Spring事务管理的方法,都会在事务执行完毕后,释放连接。Spring JDBCDataSourceUtils类释放连接的代码解释如下:

public static void doReleaseConnection(Connection con, DataSource dataSource) throws SQLException {		if (con == null) {			return;		}		if (dataSource != null) {			// 如果使用了事务管理,则调用conHolder.released()释放连接,而不关闭			ConnectionHolder conHolder = (ConnectionHolder) TransactionSynchronizationManager.getResource(dataSource);			if (conHolder != null && connectionEquals(conHolder, con)) {				// It's the transactional Connection: Don't close it.				conHolder.released();				return;			}		}		logger.debug("Returning JDBC Connection to DataSource");		// 如果没有事务管理,则调用con.close()关闭连接		doCloseConnection(con, dataSource);	}

3、将MySQL数据库的wait_time参数调小。这个要看实际情况,低并发且大多用短连接连接数据库的服务,可以调小,高并发的断开重连会造成MySQL数据库服务器的CPU上下文切换非常严重,也会导致CPUCS非常高。

4、调整连接池参数。这个根据实际情况做调整吧。

参考链接

 转载至链接:https://my.oschina.net/dabird/blog/2045592。