使用C3P0連線池的連線洩露診斷方法
阿新 • • 發佈：2019-02-07
設定C3P0的log輸出
為了能看到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:506) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection (C3P0PooledConnectionPool.java:525) at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection (AbstractPoolBackedDataSource.java:128) at aurora.database.service.SqlServiceContext.initConnection(SqlServiceContext.java:168) at aurora.database.service.BusinessModelService.prepareForRun(BusinessModelService.java:112) at aurora.database.service.BusinessModelService.query(BusinessModelService.java:188) at aurora.database.actions.ModelQuery.doQuery(ModelQuery.java:53) at aurora.database.actions.AbstractQueryAction.query(AbstractQueryAction.java:104) at aurora.database.actions.AbstractQueryAction.run(AbstractQueryAction.java:115) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:253) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:290) at uncertain.proc.Procedure.run(Procedure.java:94) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:247) at aurora.application.features.AbstractProcedureInvoker.runProcedure(AbstractProcedureInvoker.java:40) at aurora.application.features.InitProcedureInvoker.doInvoke(InitProcedureInvoker.java:33) at aurora.application.features.InitProcedureInvoker.onCreateModel(InitProcedureInvoker.java:37) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at uncertain.proc.ReflectionMethodHandle.handleEvent(ReflectionMethodHandle.java:93) at uncertain.proc.ReflectionMethodHandle.handleEvent(ReflectionMethodHandle.java:50) at uncertain.event.Configuration.fireEventInternal(Configuration.java:403) at uncertain.event.Configuration.fireEvent(Configuration.java:341) at uncertain.proc.ProcedureRunner.fireEvent(ProcedureRunner.java:312) at uncertain.proc.Action.run(Action.java:171) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:253) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:290) at uncertain.proc.Procedure.run(Procedure.java:94) at uncertain.proc.Switch.run(Switch.java:87) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:253) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:290) at uncertain.proc.Procedure.run(Procedure.java:94) at uncertain.proc.ProcedureRunner.run(ProcedureRunner.java:247) at aurora.service.ServiceInstance.invoke(ServiceInstance.java:124) at aurora.service.http.AbstractFacadeServlet.service(AbstractFacadeServlet.java:116) at javax.servlet.http.HttpServlet.service(HttpServlet.java:722) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:306) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:240) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:164) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:100) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:541) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:383) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:243) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:188) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:166) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:288) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:680)
這就是C3P0發現連線1秒鐘後沒有歸還，強制關閉連線後丟擲的資訊，從stack trace中可以看出，獲取連線是發生在aurora.database.service.BusinessModelService.query，也就是呼叫BM的query。
由於頁面確實是需要使用連線超過1秒，正在使用的連線被強制關閉以後，還會看到這樣的資訊：
011-6-22 13:24:15 com.mchange.v2.c3p0.impl.NewPooledConnection handleThrowable 警告: [c3p0] A PooledConnection that has already signalled a Connection error is still in use!
後續SQL操作再使用這個連線時，會發現連線已經關閉，於是就會丟擲類似這樣的異常：
2011-6-22 13:24:15 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:134) at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:179) at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:269) at oracle.jdbc.driver.OracleConnection.rollback(OracleConnection.java:1439) at com.mchange.v2.c3p0.impl.NewProxyConnection.rollback(NewProxyConnection.java:855) at aurora.transaction.UserTransactionImpl.rollback(UserTransactionImpl.java:58) at aurora.service.http.AbstractFacadeServlet.service(AbstractFacadeServlet.java:141) at javax.servlet.http.HttpServlet.service(HttpServlet.java:722) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:306) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:240) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:164) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:100) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:541) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:383) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:243) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:188) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:166) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:288) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:680)