Discussions

General J2EE: Hibernate inserting MANY duplicate records for a bag

  1. I have a serious problem which seems like a very serious bug in hibernate. Suddenly, after 9 months of perfect operation, my production tomcat/spring server started throwing exceptions of communication link failures to mysql. Typical stack trace is below. Seemed like there was an issue with the server itself (houses both mysql and tomcat). Web requests would sometimes be so slow they would timeout and I'd have to restart the server. So I just moved everything to a new server. Ran perfectly for half a day and then these errors started resuming! I realized that for my Person table, I had a hibernate "bag" called profileVisits. Basically I record every visit to a profile with IP, date, affiliate, referring url, etc. When I do a person.getProfileVisits().add(new ProfileVisit(request)) it actually retrieves every single profileVisit that person has ever had. And, though very inefficient, that wouldn't bother me so much except for the fact that hibernate is adding many duplicates with that statement for some reason. Sometimes it adds 1 extra duplicate, sometimes it adds 500 duplicates!!! I removed duplicates and basically deleted a ton of old profile visits data and now everything runs smooth (though the duplicate issue still exists to a very small extent, create 1 extra duplicate sometimes). Interestingly, this duplicate problem happens on other bags like my Login_Attempt table. Because all my other bags have far less activity than Profile_Visit, nothing's been affected by them and they never have more than 1 extra duplicate inserted. So 3 questions: * Why is hibernate not retrieving my bag lazily so that getProfileVisits().add() only adds a record? * Why is hibernate inserting a random number of duplicates when I only call add() once? * Why am I getting exceptions like the one below even if database activity is incredibly inefficient (one person had almost a million duplicate profile visits) with these bags? I would expect things to work, albeit maybe slowly. 2009-10-04 17:54:22,560 ERROR [http-80-10] TransactionInterceptor - Application exception overridden by rollback exception org.hibernate.exception.JDBCConnectionException: could not initialize a collection: [com.treert.people.Person.visits#2791] at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:74) at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43) at org.hibernate.loader.Loader.loadCollection(Loader.java:1999) at org.hibernate.loader.collection.CollectionLoader.initialize(CollectionLoader.java:36) at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:564) at org.hibernate.event.def.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:60) at org.hibernate.impl.SessionImpl.initializeCollection(SessionImpl.java:1720) at org.hibernate.collection.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:344) at org.hibernate.collection.AbstractPersistentCollection.write(AbstractPersistentCollection.java:183) at org.hibernate.collection.PersistentBag.add(PersistentBag.java:274) at com.treert.people.PersonManagerDao.addVisit(PersonManagerDao.java:1463) at sun.reflect.GeneratedMethodAccessor443.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:310) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106) - Show quoted text - at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) at $Proxy3.addVisit(Unknown Source) at com.treert.web.PersonController.personModel(PersonController.java:82) at com.treert.web.PersonController.display(PersonController.java:61) at sun.reflect.GeneratedMethodAccessor440.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.doInvokeMethod(HandlerMethodInvoker.java:409) at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(HandlerMethodInvoker.java:132) at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:310) at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.handle(AnnotationMethodHandlerAdapter.java:297) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:875) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:809) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:571) at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:501) at javax.servlet.http.HttpServlet.service(HttpServlet.java:617) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:96) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:378) at org.springframework.security.intercept.web.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:109) at org.springframework.security.intercept.web.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:83) at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390) at org.springframework.security.ui.ExceptionTranslationFilter.doFilterHttp(ExceptionTranslationFilter.java:101) at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53) at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390) at org.springframework.security.providers.anonymous.AnonymousProcessingFilter.doFilterHttp(AnonymousProcessingFilter.java:105) at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53) at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390) at org.springframework.security.ui.rememberme.RememberMeProcessingFilter.doFilterHttp(RememberMeProcessingFilter.java:109) at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53) at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390) at org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter.doFilterHttp(SecurityContextHolderAwareRequestFilter.java:91) at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53) at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390) at org.springframework.security.ui.basicauth.BasicProcessingFilter.doFilterHttp(BasicProcessingFilter.java:174) at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53) at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390) at org.springframework.security.ui.AbstractProcessingFilter.doFilterHttp(AbstractProcessingFilter.java:277) at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53) at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390) at org.springframework.security.ui.logout.LogoutFilter.doFilterHttp(LogoutFilter.java:89) at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53) at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390) at org.springframework.security.context.HttpSessionContextIntegrationFilter.doFilterHttp(HttpSessionContextIntegrationFilter.java:235) at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53) at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390) at org.springframework.security.securechannel.ChannelProcessingFilter.doFilterHttp(ChannelProcessingFilter.java:116) at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53) at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390) at org.springframework.security.util.FilterChainProxy.doFilter(FilterChainProxy.java:175) at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:236) at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at com.treert.web.filter.SelectivelyRemoveSessionIdInUrl.doFilter(SelectivelyRemoveSessionIdInUrl.java:38) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:567) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454) at java.lang.Thread.run(Thread.java:619) Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure Last packet sent to the server was 312081 ms ago. at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27) at java.lang.reflect.Constructor.newInstance(Constructor.java:513) at com.mysql.jdbc.Util.handleNewInstance(Util.java:406) at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1074) at com.mysql.jdbc.MysqlIO.nextRowFast(MysqlIO.java:1642) at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1398) at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2816) at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:467) at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2510) at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1746) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2135) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542) at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734) at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93) at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:184) at org.hibernate.loader.Loader.getResultSet(Loader.java:1785) at org.hibernate.loader.Loader.doQuery(Loader.java:674) at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236) at org.hibernate.loader.Loader.loadCollection(Loader.java:1992) ... 91 more Caused by: java.io.EOFException: Can not read response from server. Expected to read 330 bytes, read 205 bytes before connection was unexpectedly lost.
  2. Quite an interesting issue Mueller, after reading the issue statement i infer that Duplicate insertions never arises on the Older machine ! Could you throw some light on the server platforms and also statistics of the network latency in both the scenarios?