如何调试数据库连接池的问题?
李小翔
2013-12-23 23:35

内容列表

服务器并发比较大的时候，可能出现数据库连接不够的问题，抛出类似 “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 来手动释放连接，否则多次调用后，就很容易导致连接池不够用了。
回过头来，如何定位这些占用连接时间过长的程序呢？
· 	确保手动获得数据库连接是使用了API：
· 	DatabaseUtils.getConnection()
· 	确保 DataSource 中，对应的数据源配置了：
· 	configClass = bropen.toolkit.orm.HibernateConfiguration
· 	在 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 日志，如：
19:22:29,431 [admin/Foobar@127.0.0.1] [http-bio-8080-exec-6] [TRACE bropen.toolkit.orm.DatasourceConnectionProvider] - getting DEFAULT connection: Thread[http-bio-8080-exec-6,5,main], numActive = 0/8
19:22:29,501 [admin/Foobar@127.0.0.1] [http-bio-8080-exec-6] [TRACE bropen.toolkit.orm.DatasourceConnectionProvider] - close connection: Thread[http-bio-8080-exec-6,5,main]-1493589126, numActive = 1/8
每条日志表明获得或者释放一个数据库连接（有可能不是真实的连接，实际要执行数据库操作的时候，才会获得真正的数据库连接），日志后面的 numActive 就表明了输出日志时，到底有多少个活动（没有释放）的连接，以及设置的最大多少个连接（DataSource 里的 maxActive 参数）。
对控制器的每个http请求，大多数都会有一对获取和关闭连接的日志，如果发现某个请求有大量的获取和关闭数据库链接的日志，也属于不正常的情况，需检查相应的代码并优化。比如 service 类的 transactional 为 true，一个常用的 taglib 里调用了这个 service，则每次调用时都会重新获得一个数据库链接，此时需要把 servie 的 transactional  设为 false，或者也可以将对应的方法改成 static 方法，并使用静态方式调用。
此外，通过下面的代码也可以获得当前的活动连接数：
BeanUtils.getBean(”dataSourceUnproxied”).getNumActive()
如果服务器请求数特别少的时候，这里的活动连接数还总是大于1，那多半就可能有连接未释放的问题。
如果 DataSource 中没有配置连接池不够时自增长（dbcp.whenExhaustedAction = 2），则当服务器抛出 Timeout waiting for idle object 异常时，日志中会自动打出一大段 TRACE 日志，这些日志里包含了所有未被释放的、获得数据库连接时的堆栈信息。
或者，可以在 console 里运行下面的代码手动输出同样的日志信息，以供随时检查：
ctx.getBean(”sessionFactory”)?.getConnectionProvider().logTraceConnections()
如果配置了多数据源，上面代码里的 sessionFactory 可以加上其他数据源的名称作为后缀，以便打印对应的数据源的信息。
示例堆栈信息如下：
19:39:09,419 [admin/Foobar@127.0.0.1] [http-bio-8080-exec-10] [TRACE bropen.toolkit.orm.DatasourceConnectionProvider] - maxActive = 8, numActive = 0, numTrace = 2
  Thread[http-bio-8080-exec-9,5,main]-1189288877: 2013-12-23 19:39:06 - 3344ms:
    0: java.lang.Thread.getStackTrace(Thread.java:1479)
    1: bropen.toolkit.orm.DatasourceConnectionProvider.traceConnectionGet(DatasourceConnectionProvider.java:180)
    2: bropen.toolkit.orm.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:85)
    3: org.hibernate.connection.ConnectionProvider$getConnection.call(Unknown Source)
    4: org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:45)
    5: org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:108)
    6: org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:112)
    7: bropen.toolkit.utils.grails.DatabaseUtils.getConnection(DatabaseUtils.groovy:195)
    8: bropen.toolkit.utils.grails.DatabaseUtils.getConnection(DatabaseUtils.groovy)
    9: bropen.toolkit.utils.grails.DatabaseUtils$getConnection.call(Unknown Source)
    10: org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:45)
    11: org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:108)
    12: org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:112)
    13: Script1.run(Script1.groovy:3)
    14: groovy.lang.GroovyShell.evaluate(GroovyShell.java:518)
    15: groovy.lang.GroovyShell.evaluate(GroovyShell.java:556)
    16: groovy.lang.GroovyShell.evaluate(GroovyShell.java:527)
    17: groovy.lang.GroovyShell$evaluate.call(Unknown Source)
    18: org.grails.plugins.console.ConsoleService.eval(ConsoleService.groovy:57)
.......
从上面的堆栈信息中，就可以很容易看出曾经是哪个线程（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，即连接池满后，继续创建新连接。