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都是一个脑子嘛？发的配置有毒啊！有毒啊！尼玛老子复制粘贴上去直接死锁了有木有！

我自己测试放在<session-factory>的内容应该是下面的

<!– <property name=”hibernate.connection.provider_class”>org.hibernate.service.jdbc.connections.internal.C3P0ConnectionProvider</property> –>
<property name=”hibernate.c3p0.max_size”>20</property>
<property name=”hibernate.c3p0.min_size”>3</property>
<property name=”hibernate.c3p0.max_statements”>0</property>
<property name=”hibernate.c3p0.idle_test_period”>120</property>
<property name=”hibernate.c3p0.acquire_increment”>1</property>
<property name=”c3p0.testConnectionOnCheckout”>true</property>
<property name=”c3p0.maxIdleTime”>25000</property>

其中注释掉的部分是因为，hibernate会根据配置文件中的内容自己去寻找默认的连接池提供类，如果没有找到则会回滚默认的类。由于c3p0在hibernate有集成的提供者，因此这句话可以忽略（hibernate 4.1.4/5.0.7亲测）

这里容易引起死锁的地方有2个，一个最小连接池大小，考虑到业务需求并不大所以我设置了3（设置5的时候貌似因为并发连接过多还是怎么所以“炸”掉了），而第二个是max_statements，这个参数表示单一连接的缓存statement数量，而不是整个连接池。

至此，部署完毕。就等待明天的测试结果了。

p.s 不要用MyEclipse自带的hibernate，否则部署c3p0到实际服务器的时候会缺少c3p0的provider类导致回滚到默认连接池。