org.springframework.jdbc.support.SQLErrorCodesFactory.getErrorCodes 阻塞线程。

Question

我正在运行一个Tomcat服务器，使用Spring v4.1.0开发的服务。我正在创建到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 调用似乎都会进入同步块。在日志中搜索包含“Looking for”和“found”的行，可以看到大约有 300 行未找到对应项的情况。这与线程被阻塞且无法前进的情况一致，因为查找调试行发生在同步块之外。

- Velo

---

为该类打开调试日志记录。我还会查看 "getErrorCodes（String）" 的内容。 - Kayaman

我已经开启了调试模式。由于问题无法可靠地重现，可能需要一些时间。它最终会发生，但可能需要一段时间。我将在获得调试结果后进行更新。 - Velo

更新了调试结果。 - Velo

synchronized 块中唯一值得怀疑的是对 JdbcUtils.extractDatabaseMetaData 的调用。所有其他代码基本上只是检查 WeakHashMaps。它还使用 DataSourceUtils.getConnection(DataSource) 检索数据库连接。这可能是出现问题的主要原因，线程挂起等待 Connection（或其他某些方面）并最终导致系统冻结。它也应该记录一些东西，您是否已启用 org.springframework.jdbc.datasource 的调试？ - Kayaman

快速搜索后，我只找到了这个，但那似乎只是程序员的问题。然而，那绝对是一个“值得挂起”的地方。 - Kayaman

Answer 1

我曾经遇到同样的问题，但后来找到了解决方案。由于jdbc连接或数据库连接没有超时属性，而默认的超时时间是永不超时，所以当队列或池已满，并且this.dataSourceCache.get（dataSource）需要另一个资源进行处理时，它将永远不会超时并且没有空间运行此行，因此它会无限期地等待。

解决方案是为jdbc或您用于数据库连接的工具设置超时时间。希望这可以帮助你。

- Leon Liang