<property name="unreturnedConnectionTimeout"><value>100</value></property>
<property name="debugUnreturnedConnectionStackTraces"><value>true</value></property>
跟踪 C3p0 连接池连接泄漏
debugUnreturnedConnectionStackTraces、unreturnedConnectionTimeout参数的说明，此篇日志进一步介绍应用这两个参数后的一些经验。
首先，为了跟踪问题，debugUnreturnedConnectionStackTraces参数肯定是设置为true的。下面主要说明 unreturnedConnectionTimeout参数的设置，unreturnedConnectionTimeout参数是在连接被应用程序 checkout后指定时间内未checkin则由连接缓冲池执行kill操作，同时打印堆栈跟踪信息。在我的应用里，maxIdleTime的设置是 120秒，所以，我把unreturnedConnectionTimeout设置成150秒，如果达到最大存活时间后，连接还是不能被连接缓冲池正常关闭，那么肯定出现了连接泄漏，此时，再过30秒后，由连接缓冲池主动执行kill。
通过以上设置后，确实收获了一些成果，通过分析日志，找到了连接泄漏问题代码。异常信息如下：
2011-04-06 15:49:42,599 INFO : com.mchange.v2.resourcepool.BasicResourcePool.removeResource(BasicResourcePool.java:1395) – Logging the stack trace by which the overdue resource was checked-out.
java.lang.Exception: DEBUG ONLY: Overdue resource check-out stack trace.
at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:506)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:82)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423)
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1547)
at org.hibernate.loader.Loader.doQuery(Loader.java:673)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236)
at org.hibernate.loader.Loader.doList(Loader.java:2220)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2104)
at org.hibernate.loader.Loader.list(Loader.java:2099)
at org.hibernate.loader.custom.CustomLoader.list(CustomLoader.java:289)
at org.hibernate.impl.SessionImpl.listCustomQuery(SessionImpl.java:1695)
at org.hibernate.impl.AbstractSessionImpl.list(AbstractSessionImpl.java:142)
at org.hibernate.impl.SQLQueryImpl.list(SQLQueryImpl.java:152)
at com.leo.dao.XXXDAO.queryXXX(XXXDAO.java:20)
at jsp_servlet._keyareas._country.__taskcdb_add._jspService(__taskcdb_add.java:195)
at weblogic.servlet.jsp.JspBase.service(JspBase.java:34)
at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)
at weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125)
at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:300)
at weblogic.servlet.internal.ServletStubImpl.onAddToMapException(ServletStubImpl.java:416)
at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:326)
at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:183)
at weblogic.servlet.internal.RequestDispatcherImpl.invokeServlet(RequestDispatcherImpl.java:526)
at weblogic.servlet.internal.RequestDispatcherImpl.forward(RequestDispatcherImpl.java:253)
通过堆栈信息，很容易就确认了问题点。这个问题点是由于DAO使用不规范导致的，XXXDAO继承了HibernateDaoSupport，在方法中使用了getHibernateTemplate().getSessionFactory().openSession()获得session，然后通过session.createSQLQuery()，随后却并没有执行session.close()。
关于日志大小：在目前 maxIdleTime=120,maxPoolSize=18,minPoolSize=5,idleConnectionTestPeriod=30 的情况下，日志PatternLayout %d %-5p: %l – %m%n，一天的日志记录情况大约是12M，在硬盘空间允许的情况下建议按天存储日志。
另一篇
http://blog.csdn.net/kaishuaige/article/details/14451423
置文件（0.datasource.config）中，设置以下属性：
debugUnreturnedConnectionStackTraces=true unreturnedConnectionTimeout=1200
其中： debugUnreturnedConnectionStackTraces是一个开关，启用之后，对于每个从连接池拿出去的数据库连接，如果一段时间内没有归还，C3P0就会强制关闭这个连接，并将获取连接时的stack trace，以抛出异常的方式显示出来。 unreturnedConnectionTimeout设置多长时间会超时，以秒为单位。
假设系统中怀疑有连接泄露，那么，就可以启用这个功能，评估所有页面执行完成需要的最长时间，例如20分钟，然后将unreturnedConnectionTimeout设置为略大于这个时间。
为了能看到C3P0抛出的异常信息，还需要设置C3P0的log属性。最简单的方式就是让C3P0使用JDK标准的log API，这样不需要加载额外的jar。在启动JVM时，设置启动参数： Dcom.mchange.v2.log.MLog=com.mchange.v2.log.jdk14logging.Jdk14MLog
在Tomcat中，可修改catalina.sh，设置JAVA_OPTS变量包含上述内容。
可以做一个测试：设置C3P0属性debugUnreturnedConnectionStackTraces=true，unreturnedConnectionTimeout=1，然后访问一个运行时间超过1秒的页面。这样，就会在tomcat的输出窗口看到这样一段信息：
信息: Logging the stack trace by which the overdue resource was checked-out. java.lang.Exception: DEBUG ONLY: Overdue resource check-out stack trace. at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:<span class="hl-number">506</span>) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection (C3P0PooledConnectionPool.java:<span class="hl-number">525</span>) at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection (AbstractPoolBackedDataSource.java:<span class="hl-number">128</span>) at aurora.database.service.SqlServiceContext.initConnection(SqlServiceContext.java:<span class="hl-number">168</span>) at aurora.database.service.BusinessModelService.prepareForRun(BusinessModelService.java:<span class="hl-number">112</span>) at aurora.database.service.BusinessModelService.query(BusinessModelService.java:<span class="hl-number">188</span>) at aurora.database.actions.ModelQuery.doQuery(ModelQuery.java:<span class="hl-number">53</span>) at aurora.database.actions.AbstractQueryAction.query(AbstractQueryAction.java:<span class="hl-number">104</span>) at aurora.database.actions.AbstractQueryAction.run(AbstractQueryAction.java:<span class="hl-number">115</span>) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:<span class="hl-number">253</span>) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:<span class="hl-number">290</span>) at uncertain.proc.Procedure.run(Procedure.java:<span class="hl-number">94</span>) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:<span class="hl-number">247</span>) at aurora.application.features.AbstractProcedureInvoker.runProcedure(AbstractProcedureInvoker.java:<span class="hl-number">40</span>) at aurora.application.features.InitProcedureInvoker.doInvoke(InitProcedureInvoker.java:<span class="hl-number">33</span>) at aurora.application.features.InitProcedureInvoker.onCreateModel(InitProcedureInvoker.java:<span class="hl-number">37</span>) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:<span class="hl-number">39</span>) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:<span class="hl-number">25</span>) at java.lang.reflect.Method.invoke(Method.java:<span class="hl-number">597</span>) at uncertain.proc.ReflectionMethodHandle.handleEvent(ReflectionMethodHandle.java:<span class="hl-number">93</span>) at uncertain.proc.ReflectionMethodHandle.handleEvent(ReflectionMethodHandle.java:<span class="hl-number">50</span>) at uncertain.event.Configuration.fireEventInternal(Configuration.java:<span class="hl-number">403</span>) at uncertain.event.Configuration.fireEvent(Configuration.java:<span class="hl-number">341</span>) at uncertain.proc.ProcedureRunner.fireEvent(ProcedureRunner.java:<span class="hl-number">312</span>) at uncertain.proc.Action.run(Action.java:<span class="hl-number">171</span>) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:<span class="hl-number">253</span>) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:<span class="hl-number">290</span>) at uncertain.proc.Procedure.run(Procedure.java:<span class="hl-number">94</span>) at uncertain.proc.Switch.run(Switch.java:<span class="hl-number">87</span>) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:<span class="hl-number">253</span>) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:<span class="hl-number">290</span>) at uncertain.proc.Procedure.run(Procedure.java:<span class="hl-number">94</span>) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:<span class="hl-number">247</span>) at aurora.service.ServiceInstance.invoke(ServiceInstance.java:<span class="hl-number">124</span>) at aurora.service.http.AbstractFacadeServlet.service(AbstractFacadeServlet.java:<span class="hl-number">116</span>) at javax.servlet.http.HttpServlet.service(HttpServlet.java:<span class="hl-number">722</span>) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:<span class="hl-number">306</span>) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:<span class="hl-number">210</span>) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:<span class="hl-number">240</span>) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:<span class="hl-number">161</span>) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:<span class="hl-number">164</span>) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:<span class="hl-number">100</span>) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:<span class="hl-number">541</span>) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:<span class="hl-number">118</span>) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:<span class="hl-number">383</span>) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:<span class="hl-number">243</span>) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:<span class="hl-number">188</span>) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:<span class="hl-number">166</span>) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:<span class="hl-number">288</span>) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:<span class="hl-number">886</span>) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:<span class="hl-number">908</span>) at java.lang.Thread.run(Thread.java:<span class="hl-number">680</span>)
这就是C3P0发现连接1秒钟后没有归还，强制关闭连接后抛出的信息，从stack trace中可以看出，获取连接是发生在aurora.database.service.BusinessModelService.query，也就是调用BM的query。
由于页面确实是需要使用连接超过1秒，正在使用的连接被强制关闭以后，还会看到这样的信息：
<span class="hl-number">011</span>-<span class="hl-number">6</span>-<span class="hl-number">22</span> <span class="hl-number">13</span>:<span class="hl-number">24</span>:<span class="hl-number">15</span> com.mchange.v2.c3p0.impl.NewPooledConnection handleThrowable 警告: [c3p0] A PooledConnection that has already signalled a Connection error is still in use!
后续SQL操作再使用这个连接时，会发现连接已经关闭，于是就会抛出类似这样的异常：
<span class="hl-number">2011</span>-<span class="hl-number">6</span>-<span class="hl-number">22</span> <span class="hl-number">13</span>:<span class="hl-number">24</span>:<span class="hl-number">15</span> com.mchange.v2.c3p0.impl.NewPooledConnection handleThrowable 警告: [c3p0] Another error has occurred [ java.sql.SQLException: 关闭的连接 ] which will not be reported to listeners! java.sql.SQLException: 关闭的连接 at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:<span class="hl-number">134</span>) at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:<span class="hl-number">179</span>) at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:<span class="hl-number">269</span>) at oracle.jdbc.driver.OracleConnection.rollback(OracleConnection.java:<span class="hl-number">1439</span>) at com.mchange.v2.c3p0.impl.NewProxyConnection.rollback(NewProxyConnection.java:<span class="hl-number">855</span>) at aurora.transaction.UserTransactionImpl.rollback(UserTransactionImpl.java:<span class="hl-number">58</span>) at aurora.service.http.AbstractFacadeServlet.service(AbstractFacadeServlet.java:<span class="hl-number">141</span>) at javax.servlet.http.HttpServlet.service(HttpServlet.java:<span class="hl-number">722</span>) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:<span class="hl-number">306</span>) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:<span class="hl-number">210</span>) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:<span class="hl-number">240</span>) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:<span class="hl-number">161</span>) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:<span class="hl-number">164</span>) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:<span class="hl-number">100</span>) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:<span class="hl-number">541</span>) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:<span class="hl-number">118</span>) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:<span class="hl-number">383</span>) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:<span class="hl-number">243</span>) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:<span class="hl-number">188</span>) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:<span class="hl-number">166</span>) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:<span class="hl-number">288</span>) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:<span class="hl-number">886</span>) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:<span class="hl-number">908</span>) at java.lang.Thread.run(Thread.java:<span class="hl-number">680</span>)
1211
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
