Hibernate之连接池坑

最近某项目遇到一个比较奇怪的情况,服务器启动大约8小时以后所有对servlet的请求都会变成404。经过测试发现浏览器可以正常访问,但是客户端就会出现错误。 考虑到404是指代资源未找到的情况,于是翻看tomcat的日志,对比浏览器请求和客户端请求,发现请求URL别无二致,但是结果却是一个302一个404。这尼玛真是搞得我百撕不得骑姐百思不得其解。 于是搞毛了上谷歌问问这算是个什么鬼情况,结果当我把tomcat 404打完的时候谷歌给了一个搜索建议叫做“Request resource is not available”,意思就是请求的资源不可用。然后这时候我就在想一般时候404不都是提示的not found之类的么?如果是按照“请求资源不可用”这个解释来说的话,那可能就是servlet执行过程出现了错误。 于是返回服务器查看近期日志,发现hibernate留下了一堆东西。。。。。

28-Jan-2016 15:21:24.268 SEVERE [http-nio-8080-exec-5] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [xxxxx] in context with path [/xxxxx] threw exception org.hibernate.TransactionException: rollback failed at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.rollback(AbstractTransactionImpl.java:215) …… at javax.servlet.http.HttpServlet.service(HttpServlet.java:622) at javax.servlet.http.HttpServlet.service(HttpServlet.java:729) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:217) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79) at org.apache.catalina.valves.RequestFilterValve.process(RequestFilterValve.java:312) at org.apache.catalina.valves.RemoteAddrValve.invoke(RemoteAddrValve.java:95) at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:616) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518) at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:673) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:745) Caused by: org.hibernate.TransactionException: unable to rollback against JDBC connection at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doRollback(JdbcTransaction.java:167) at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.rollback(AbstractTransactionImpl.java:209) … 29 more Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed. at sun.reflect.GeneratedConstructorAccessor22.newInstance(Unknown Source) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:422) at com.mysql.jdbc.Util.handleNewInstance(Util.java:408) at com.mysql.jdbc.Util.getInstance(Util.java:383) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1023) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:997) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:983) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:928) at com.mysql.jdbc.ConnectionImpl.throwConnectionClosedException(ConnectionImpl.java:1314) at com.mysql.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:1306) at com.mysql.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:5048) at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doRollback(JdbcTransaction.java:163) … 30 more Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure The last packet successfully received from the server was 2,668,684 milliseconds ago. The last packet sent successfully to the server was 1 milliseconds ago. at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:422) at com.mysql.jdbc.Util.handleNewInstance(Util.java:408) at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1137) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3697) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3586) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4131) at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2597) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2758) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2826) at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2082) at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2212) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.hibernate.engine.jdbc.internal.proxy.AbstractStatementProxyHandler.continueInvocation(AbstractStatementProxyHandler.java:122) at org.hibernate.engine.jdbc.internal.proxy.AbstractProxyHandler.invoke(AbstractProxyHandler.java:81) at com.sun.proxy.$Proxy5.executeQuery(Unknown Source) at org.hibernate.loader.Loader.getResultSet(Loader.java:1953) at org.hibernate.loader.Loader.doQuery(Loader.java:829) at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:289) at org.hibernate.loader.Loader.doList(Loader.java:2438) at org.hibernate.loader.Loader.doList(Loader.java:2424) at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2254) at org.hibernate.loader.Loader.list(Loader.java:2249) at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:470) at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:355) at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:195) at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1248) at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101) at cn.sunflyer.simpnk.web.dao.HibernateDao.doQuery(HibernateDao.java:96) … 28 more Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost. at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3143) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3597) … 55 more

对比出现故障的时间间隔发现这段日志的时间是在故障时间内,因此判断可能是由于数据库的操作导致了tomcat的404错误。 搜索错误信息中加粗部分后得知,hibernate默认的连接池不检查连接的有效性。而在一般情况下MySQL对一个连接的最大有效期是8小时。这个时间也和前面发现的故障间隔时间一致。这也让我更加确定问题是hibernate的连接池问题。 那么话不多说,肯定是处理连接池空闲咯。网上找了下说什么hibernate默认连接池是没有有效性检测的,可以用proxo或者c3p0等方式操作。这里我用了c3p0。 当然,我还是走了很多坑,比如,不应该轻易相信中文搜索结果。尼玛,搜索出c3p0配置逗TM是惊人的一致,你们这几些博主难道就TM都是一个脑子嘛?发的配置有毒啊!有毒啊!尼玛老子复制粘贴上去直接死锁了有木有! 我自己测试放在的内容应该是下面的

<!-- org.hibernate.service.jdbc.connections.internal.C3P0ConnectionProvider –> 20 3 0 120 1 true 25000

其中注释掉的部分是因为,hibernate会根据配置文件中的内容自己去寻找默认的连接池提供类,如果没有找到则会回滚默认的类。由于c3p0在hibernate有集成的提供者,因此这句话可以忽略(hibernate 4.1.4/5.0.7亲测) 这里容易引起死锁的地方有2个,一个最小连接池大小,考虑到业务需求并不大所以我设置了3(设置5的时候貌似因为并发连接过多还是怎么所以“炸”掉了),而第二个是max_statements,这个参数表示单一连接的缓存statement数量,而不是整个连接池。 至此,部署完毕。就等待明天的测试结果了。 p.s 不要用MyEclipse自带的hibernate,否则部署c3p0到实际服务器的时候会缺少c3p0的provider类导致回滚到默认连接池。