org.springframework.jdbc.support.SQLErrorCodesFactory.getErrorCodes 阻塞线程答案

【问题标题】：org.springframework.jdbc.support.SQLErrorCodesFactory.getErrorCodes is blocking threadsorg.springframework.jdbc.support.SQLErrorCodesFactory.getErrorCodes 阻塞线程
【发布时间】：2016-01-27 11:10:34
【问题描述】：

我正在运行一个带有使用 spring v 4.1.0 开发的服务的 tomcat 服务器。我正在创建与 informix 数据库的 jdbc 连接，但偶尔会出现错误。这些连接是单个连接而不是池化的（因为我根据不同的输入标准连接到动态生成的数据库主机）。

随着时间的推移，一切似乎都进展顺利，然后突然之间，我开始大量上升 tomcat 线程，这种上升一直持续到我达到最大线程数并且对服务器的所有请求都被拒绝。进行线程转储显示所有线程都挂在 org.springframework.jdbc.support.SQLErrorCodesFactory.getErrorCodes 上。

- org.springframework.jdbc.support.SQLErrorCodesFactory.getErrorCodes(javax.sql.DataSource) @bci=56, line=204 (Interpreted frame)
- org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.setDataSource(javax.sql.DataSource) @bci=5, line=134 (Interpreted frame)
- org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.<init>(javax.sql.DataSource) @bci=6, line=97 (Interpreted frame)
- org.springframework.jdbc.support.JdbcAccessor.getExceptionTranslator() @bci=22, line=99 (Interpreted frame)
- org.springframework.jdbc.support.JdbcAccessor.afterPropertiesSet() @bci=25, line=138 (Interpreted frame)
- org.springframework.jdbc.core.JdbcTemplate.<init>(javax.sql.DataSource, boolean) @bci=50, line=182 (Interpreted frame)
- com.business.stores.data.dao.impl.BaseDAOImpl.getJdbcTemplate(int) @bci=86, line=53 (Interpreted frame)
...

我已经提取了上面列出的 spring 类的源代码，其中有一个同步块，但我不确定它为什么无法执行并挂起系统中的所有线程。（似乎在它被阻塞后，任何后续 SQL 错误也会阻塞，直到盒子上没有可用的线程。这是来自 Spring 的代码：

public SQLErrorCodes getErrorCodes(DataSource dataSource) {
    Assert.notNull(dataSource, "DataSource must not be null");
    if (logger.isDebugEnabled()) {
        logger.debug("Looking up default SQLErrorCodes for DataSource [" + dataSource + "]");
    }

    synchronized (this.dataSourceCache) {
        // Let's avoid looking up database product info if we can.
        SQLErrorCodes sec = this.dataSourceCache.get(dataSource);
        if (sec != null) {
            if (logger.isDebugEnabled()) {
                logger.debug("SQLErrorCodes found in cache for DataSource [" +
                        dataSource.getClass().getName() + '@' + Integer.toHexString(dataSource.hashCode()) + "]");
            }
            return sec;
        }
        // We could not find it - got to look it up.
        try {
            String dbName = (String) JdbcUtils.extractDatabaseMetaData(dataSource, "getDatabaseProductName");
            if (dbName != null) {
                if (logger.isDebugEnabled()) {
                    logger.debug("Database product name cached for DataSource [" +
                            dataSource.getClass().getName() + '@' + Integer.toHexString(dataSource.hashCode()) +
                            "]: name is '" + dbName + "'");
                }
                sec = getErrorCodes(dbName);
                this.dataSourceCache.put(dataSource, sec);
                return sec;
            }
        }
        catch (MetaDataAccessException ex) {
            logger.warn("Error while extracting database product name - falling back to empty error codes", ex);
        }
    }

    // Fallback is to return an empty SQLErrorCodes instance.
    return new SQLErrorCodes();
}

-------更新在这一点上，我不知道什么是锁定 dataSourceCache 或如何修复它。

打开 spring 模块的日志记录（和调试），然后通过使用不同环境中的站点（因此使用不同的密码）调用服务来强制问题。服务按预期返回了无效的密码响应，但日志中有这些行。

似乎已正确加载数据：

2015-10-27 21:09:26,677||DEBUG||SQLErrorCodesFactory.getErrorCodes(175)||||SQL error codes for 'Informix Dynamic Server' found

但它在检索数据时遇到了某种问题：

2015-10-27 21:09:33,162||DEBUG||SQLErrorCodesFactory.getErrorCodes(199)||||Looking up default SQLErrorCodes for DataSource [org.springframework.jdbc.datasource.SingleConnectionDataSource@149e2931]
2015-10-27 21:09:34,254||DEBUG||SQLErrorCodesFactory.getErrorCodes(217)||||Database product name cached for DataSource [org.springframework.jdbc.datasource.SingleConnectionDataSource@50e91794]: name is 'Informix Dynamic Server'

2015-10-27 21:09:34,255||INFO ||MarkdownVoidByCashierDAOImpl.getVoidByCashierFromStore(47)||||Created JDBC Template for 68

然后它抛出了我预期的错误：

2015-10-27 21:09:34,317||WARN ||SQLErrorCodesFactory.getErrorCodes(227)||||Error while extracting database product name - falling back to empty error codes
org.springframework.jdbc.support.MetaDataAccessException: Could not get Connection for extracting meta data; nested exception is org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: Incorrect password or user com.informix.asf.IfxASFRemoteException: user1@::ffff:10.63.112.131 is not known on the database server.
        at org.springframework.jdbc.support.JdbcUtils.extractDatabaseMetaData(JdbcUtils.java:297)
        at org.springframework.jdbc.support.JdbcUtils.extractDatabaseMetaData(JdbcUtils.java:324)
        at org.springframework.jdbc.support.SQLErrorCodesFactory.getErrorCodes(SQLErrorCodesFactory.java:214)
        at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.setDataSource(SQLErrorCodeSQLExceptionTranslator.java:134)
        at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.<init>(SQLErrorCodeSQLExceptionTranslator.java:97)
        at org.springframework.jdbc.support.JdbcAccessor.getExceptionTranslator(JdbcAccessor.java:99)
        at org.springframework.jdbc.support.JdbcAccessor.afterPropertiesSet(JdbcAccessor.java:138)
        at org.springframework.jdbc.core.JdbcTemplate.<init>(JdbcTemplate.java:182)
...

当然，这似乎也没有重现问题（我真的没想到会，之前重现问题的尝试都失败了）所以我会继续监控直到问题再次出现。

-----更新 2

所以问题在盒子上再次出现。虽然通过调试查看日志，但我并没有看到太多可以指出根本原因的东西。

我一遍又一遍地看到这种基本模式：

2015-10-27 21:28:11,178||DEBUG||SQLErrorCodesFactory.getErrorCodes(199)||||Looking up default SQLErrorCodes for DataSource [org.springframework.jdbc.datasource.SingleConnectionDataSource@3da15c49]
...
2015-10-27 21:28:13,481||DEBUG||SQLErrorCodesFactory.getErrorCodes(217)||||Database product name cached for DataSource [org.springframework.jdbc.datasource.SingleConnectionDataSource@207e4667]: name is 'Informix Dynamic Server'
2015-10-27 21:28:13,482||DEBUG||SQLErrorCodesFactory.getErrorCodes(175)||||SQL error codes for 'Informix Dynamic Server' found

单连接数据源末尾的十六进制值是唯一改变的东西。

出现一两个错误时，我看到以下内容：

2015-10-27 21:27:33,622||WARN ||SQLErrorCodesFactory.getErrorCodes(227)||||Error while extracting database product name - falling back to empty error codes

但我相信只有当我将完全无效的服务器名称作为目标时才会出现。看起来它确实进入了每个 SQL 调用的同步块。日志中包含“正在寻找”与“找到”的行的 grep 显示大约 300 的差异，其中查找没有达到相应的发现。这与线程阻塞和无法前进是一致的，因为正在查找的调试行发生在同步块之外。

【问题讨论】：

开启该类的调试日志。我还要看看getErrorCodes(String)的内容。
我已打开调试。这可能需要一段时间，因为该问题无法可靠地重现。它最终会发生，但可能需要一段时间。当我有调试结果时，我会更新它们。
已更新调试结果
synchronized 块中唯一值得怀疑的事情是对JdbcUtils.extractDatabaseMetaData 的调用。所有其他代码基本上只是检查WeakHashMaps。它还使用DataSourceUtils.getConnection(DataSource) 检索数据库连接。这将是出现问题的主要候选者，线程挂起等待Connection（或在其他方面）并最终冻结系统。它也应该记录一些东西，你是否为org.springframework.jdbc.datasource启用了调试？
快速搜索我只找到this，但这似乎只是程序员的错。然而，这绝对是一个“值得挂”的地方。

标签： java spring jdbc spring-jdbc

【解决方案1】：

我遇到了同样的问题，但我找到了解决方案。因为jdbc连接或者数据库连接没有超时属性并且默认超时是永不超时，所以在队列或者池满后，this.dataSourceCache.get(dataSource);需要另一个资源来处理，所以它永远不会超时并且没有空间来运行这一行，所以它永远在这里等待。

解决办法是设置jdbc的超时时间或者你用于数据库连接的超时时间。希望它会有所帮助。

【讨论】：