如何调试数据库连接池的问题?

服务器并发比较大的时候，可能出现数据库连接不够的问题，抛出类似 “Timeout waiting for idle object” 的异常，BroToolkit 提供了一个自定义的 Hibernate 配置类（bropen.toolkit.orm.HibernateConfiguration），除了能用来处理 Oracle 等排序问题外，还可以用来对数据库连接的获取与释放进行跟踪，以便定位是否有长时间未关闭连接的代码。

在此之前，先看看 Web 请求中的数据连接问题。

Grails 采取了经典的 OpenSessionInView 方式来处理数据库连接。通过浏览器访问控制器时，会自动生成一个 Hibernate 的 Session，如果使用了数据库相关的操作，则会自动获取数据库连接，请求结束时自动释放数据库连接。

这种模式下，如果每个请求都能比较快速的执行完毕，通常是不会发生数据库连接溢出的问题；但如果控制器执行时间比较长，并且并发请求比较多的时候，就容易导致连接不够用。比如下面两种情况：

• 控制器中执行大量的运算，导致执行时间过长
• 控制器中执行了请求外部资源的一些操作（比如调用 HttpUtils 或者 WebService 来请求第三方系统的资源），并且这些操作都设置了较长的超时时间（比如HttpUtils里默认30"），如果第三方系统响应太慢或者宕机。

这种情况导致的连接溢出，一般来说主要是优化代码，比如：

• 避免大量运算的并发操作
• 请求外部资源时设置较小的超时时间
• 使用 domain.withNewSession 将数据库相关的操作与请求外部资源的代码段隔离开

当不是Web请求时，比如 Quartz Job、runAsync 等方法，都会采用类似的方式类保证执行前后自动获取和释放连接，因此可以用相同的优化方式处理。

但是，如果程序中使用 DatabaseUtils.getConnection() 方法类获取的数据库连接，则必须调用 DatabaseUtils.closeConnection 来手动释放连接，否则多次调用后，就很容易导致连接池不够用了。

回过头来，如何定位这些占用连接时间过长的程序呢？

1. 确保手动获得数据库连接是使用了API：
   DatabaseUtils.getConnection()
2. 确保 DataSource 中，对应的数据源配置了：
   configClass = bropen.toolkit.orm.HibernateConfiguration
3. 在 Config 里添加日志选项：
   trace 'bropen.toolkit.orm.DatasourceConnectionProvider'
   // 默认已开启
   debug grails.app.filters.BroFrameworkFilters
   如果在运行时，可以在console中执行下面的代码动态开启：
   org.apache.log4j.Logger.getLogger("bropen.toolkit.orm.DatasourceConnectionProvider").level = org.apache.log4j.Level.TRACE;

上面的准备工作完成后（主要是2、3），应用的日志中会输出大量的 TRACE 日志，如：

每条日志表明获得或者释放一个数据库连接（有可能不是真实的连接，实际要执行数据库操作的时候，才会获得真正的数据库连接），日志后面的 numActive 就表明了输出日志时，到底有多少个活动（没有释放）的连接，以及设置的最大多少个连接（DataSource 里的 maxActive 参数）。

对控制器的每个http请求，大多数都会有一对获取和关闭连接的日志，如果发现某个请求有大量的获取和关闭数据库链接的日志，也属于不正常的情况，需检查相应的代码并优化。比如 service 类的 transactional 为 true，一个常用的 taglib 里调用了这个 service，则每次调用时都会重新获得一个数据库链接，此时需要把 servie 的 transactional  设为 false，或者也可以将对应的方法改成 static 方法，并使用静态方式调用。

此外，通过下面的代码也可以获得当前的活动连接数：

如果服务器请求数特别少的时候，这里的活动连接数还总是大于1，那多半就可能有连接未释放的问题。

如果 DataSource 中没有配置连接池不够时自增长（dbcp.whenExhaustedAction = 2），则当服务器抛出 Timeout waiting for idle object 异常时，日志中会自动打出一大段 TRACE 日志，这些日志里包含了所有未被释放的、获得数据库连接时的堆栈信息。

或者，可以在 console 里运行下面的代码手动输出同样的日志信息，以供随时检查：

如果配置了多数据源，上面代码里的 sessionFactory 可以加上其他数据源的名称作为后缀，以便打印对应的数据源的信息。

示例堆栈信息如下：

从上面的堆栈信息中，就可以很容易看出曾经是哪个线程（http-bio-8080-exec-9）、通过怎样的调用过程（堆栈）拿到了一个数据库连接，并且从 19:39:06 到现在，已执行了 3344ms 却一直没有释放。

如果堆栈信息提供的信息还不够完整，还可以从日志里去查找对应时间点的线程执行情况，如下面的日志说明 HTTP 线程 http-bio-8080-exec-3 已执行完成，总耗时29ms：
.... [http-bio-8080-exec-3] [DEBUG grails.app.filters.BroFrameworkFilters] - 4, 29 + 0 = 29ms for GET portal/index
如果发现线程执行完成，但是数据库连接未释放，则可能是有手动获得的数据库连接未关闭，需要在 finally 里执行关闭API：DatabaseUtils.closeConnection()

不过，如果是通过 DatabaseUtils.getSql 打开的数据库连接，关闭后可能仍然会出现在上面的堆栈日志中，好在相关的代码都比较好查，使用完毕后，在 finally 里将 sql 对象 close 即可。

最后，如果定位到了问题所在，该手动关闭的数据库连接也调用 API 正常关闭了，之前所提到的几种代码优化也都做了，仍然时不时出现 “Timeout waiting for idle object” 异常，可以在 DataSouce 中的 hibernate.properties[_xxxx] 中设置 dbcp.whenExhaustedAction = 2，即连接池满后，继续创建新连接。