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类导致回滚到默认连接池。

评论

13条评论
  1. Gravatar 头像

    AdventCirno

    peropero

  2. Gravatar 头像

    初音ミク酱

    SimpleNetkeeper支不支持极路由呢?我用的极2

    • Gravatar 头像

      crazychen

      @初音ミク酱 极路由属于Openwrt分支,请参考github上的Openwrt-Netkeeper项目

      • Gravatar 头像

        初音ミク酱

        @crazychen 现在极路由根本不能用特殊模式登陆网,更不用说刷机了T_T,而且我也不会刷OpenWrt,不知道刷完后路由器系统会变成啥样,目前可以用网线插WAN口关闭dhcp用手机连路由器,下载个wifikeeper(经常闪退垃圾软件)输入帐号密码滑动就可以上网(限制2台机器),真是麻烦啊,希望能直接连路由器就好了。

        • Gravatar 头像

          crazychen

          @初音ミク酱 不是刷,是编个插件丢上去。之前有几个同学也是江西的反馈说用OP登录貌似不会掉线,然而带宽会缩水。。。。

          • Gravatar 头像

            初音ミク酱

            @crazychen 今天已经把极2刷了openwrt,用ubuntu编译了so文件放进去了,可是还是连不上,看了下编译界面有个warning: mipsel-openwrt-linux-uclibc-gcc.bin: warning: environment variable 'STAGING_DIR' not defined
            不知道是这个原因吗,折腾了一下午还没搞好T_T
            ,求大大看看哪里出错了。

          • Gravatar 头像

            crazychen

            @初音ミク酱 和编译警告无关的,你要到OP的管理界面,系统-》系统日志 看是不是有类似于 PPPoE Doscovery Timed out , 或者 Pin code error之类的

          • Gravatar 头像

            初音ミク酱

            @crazychen 看来so无问题,路由器界面显示已连接,但是电脑不能上网,电脑ping不行,路由器内部ping可以,到底怎么回事,快要哭晕了

          • Gravatar 头像

            crazychen

            @初音ミク酱 上不了网的话在拨号之前,到放火墙,把Netkeeper的接口拉到WAN区域去。再拨号就OK了

          • Gravatar 头像

            初音ミク酱

            @crazychen 后来搞进去还是没能成功T_T LAN口需要设置吗?

          • Gravatar 头像

            初音ミク酱

            @crazychen 我重置openwrt再设置后现在根本不能连上了,怎么办啊

          • Gravatar 头像

            crazychen

            @初音ミク酱 重启路由器,这边显示的是你请求太多了,拔掉网线或者重启路由器,等三分钟