11 Replies Latest reply on Sep 14, 2004 8:52 AM by belaban

    ConcurrentModificationException in log.debug() statement

    austvold

      Hi,

      I'm using JbossCache1_1, and found that this exception occured occationally.

      For some reason the statement

      log.debug("commit(): releasing lock " + lock);

      on line 2792 in TreeCache.java.

      Best regards,
      Ørjan



      ERROR 2004-09-03 09:54:32,098 [unknown ] [http8888-Processor10] org.jboss.cache.interceptors.OrderedSynchronizationHandler.afterCompletion - failed calling afterCompletion() on org.jboss.cache.interceptors.TransactionInterceptor$SynchronizationHandler@b471fe
      java.util.ConcurrentModificationException
      at java.util.AbstractList$Itr.checkForComodification(AbstractList.java:448)
      at java.util.AbstractList$Itr.next(AbstractList.java:419)
      at java.util.AbstractCollection.toString(AbstractCollection.java:454)
      at java.lang.String.valueOf(String.java:2131)
      at java.lang.StringBuffer.append(StringBuffer.java:370)
      at org.jboss.cache.lock.IdentityLock.toString(IdentityLock.java:303)
      at java.lang.String.valueOf(String.java:2131)
      at java.lang.StringBuffer.append(StringBuffer.java:370)
      at org.jboss.cache.TreeCache.commit(TreeCache.java:2792)
      at org.jboss.cache.interceptors.TransactionInterceptor$SynchronizationHandler.afterCompletion(TransactionInterceptor.java:103)
      at org.jboss.cache.interceptors.OrderedSynchronizationHandler.afterCompletion(OrderedSynchronizationHandler.java:79)
      at org.objectweb.jotm.SubCoordinator.doAfterCompletion(SubCoordinator.java:1149)
      at org.objectweb.jotm.SubCoordinator.doOnePhaseCommit(SubCoordinator.java:914)
      at org.objectweb.jotm.SubCoordinator.commit_one_phase(SubCoordinator.java:397)
      at org.objectweb.jotm.TransactionImpl.commit(TransactionImpl.java:219)
      at org.objectweb.jotm.Current.commit(Current.java:442)
      at net.sf.hibernate.transaction.JTATransaction.commit(JTATransaction.java:56)
      at com.colibria.util.persistence.hibernate.SessionFactory.closeSession(SessionFactory.java:193)
      at com.colibria.ccc.api.CCCFactory$InterceptedHandler.invoke(CCCFactory.java:278)
      at $Proxy4.login(Unknown Source)
      at com.colibria.apps.csp12.sap.TransactionDispatcher.processOutbandTRC12(TransactionDispatcher.java:874)
      at com.colibria.apps.csp12.sap.TransactionDispatcher.processCSP12(TransactionDispatcher.java:224)
      at com.colibria.apps.csp12.sap.XMLPipe.doPost(XMLPipe.java:152)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:760)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:247)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:193)
      at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:256)
      at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:643)
      at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:480)
      at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
      at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
      at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:643)
      at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:480)
      at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
      at org.apache.catalina.core.StandardContext.invoke(StandardContext.java:2422)
      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:180)
      at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:643)
      at org.apache.catalina.valves.ErrorDispatcherValve.invoke(ErrorDispatcherValve.java:171)
      at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:641)
      at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:163)
      at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:641)
      at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:480)
      at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
      at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:174)
      at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:643)
      at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:480)
      at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
      at org.apache.coyote.tomcat4.CoyoteAdapter.service(CoyoteAdapter.java:199)
      at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:828)
      at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:700)
      at org.apache.tomcat.util.net.TcpWorkerThread.runIt(PoolTcpEndpoint.java:584)
      at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:683)
      at java.lang.Thread.run(Thread.java:534)

        • 1. Re: ConcurrentModificationException in log.debug() statement
          norbert

          I've notices these kind of exceptions in many areas of jboss-cache's 'toString()' methods...

          It's because all the Collections being used (e.g. ArrayList for readOwnerList in LockMap.java, HashMap for data in Node.java ... ) are all unsynchronized and throw ConcurrentModificationException whenever being modified in another thread while being iterated.

          • 2. Re: ConcurrentModificationException in log.debug() statement
            norbert

            e.g. in NodeMap it dosn't help that the method readerOwners() is synchronized, but the Collection (readOwnerList_) being returned by it being unsynchronized.

            It wouldn't even help to make the IdentityLock.toString()-method synchronized, since the JVM's lock on the IdentityLock instance does not lock the NodeMap, which would be required to hinder the NodeMap's synchronized method's (which lock the NodeMap, but not it's instance-variables) to excecute and modify the concurrenty accessed readOwnerList_....

            IMHO the only way to archive this is to use the synchronized version instead(created by java.util.Collection.synchronizedCollection(Collection)).

            • 3. Re: ConcurrentModificationException in log.debug() statement
              norbert

              btw:

              this is not just an issue of debugging - other methods like the various 'printInfo()' (even in TreeCache()) eventually throwsConcurrentModificationException when being called while the cache is in use.

              If we want to keep the underlying Collections unsynchronized for performance-reasons, we must never pass references to them. methods like 'LockMap.readerOwners()' are a 'must not' in respect to concurrency.

              I guess all the synchronizing must be carefully reviewed before this may go gold.

              • 4. Re: ConcurrentModificationException in log.debug() statement

                I think this is a good point. I can see this exception probably doesn't happen that often with REPEATABLE_READ and up. But with more relaxed isolation levels, it can be a problem.

                Bela and I will be meeting soon. We should visit issue. What do you think, Bela?

                -Ben

                • 5. Re: ConcurrentModificationException in log.debug() statement
                  belaban

                  Yes. I'm willing to pay the price for occasional exceptions though in print() methods, but would not want to synchronize them at all.

                  Norbert et al: Keep those bug reports coming !

                  Bela

                  • 6. Re: ConcurrentModificationException in log.debug() statement
                    norbert

                    bela:

                    the price is that a business-transaction might fail just because loglevel is set to 'INFO'....

                    I don't think this is a real good idea.

                    • 7. Re: ConcurrentModificationException in log.debug() statement
                      norbert

                      my company (100000 empl., several hundred instances of J2EE-application-servers) is planning to use JBoss application-server in production starting 2005. I'll be technically responsible for this.
                      From an enterprise customers standpoint anything that is known to fail 'every now and then' is not just being seen as bad programming practice, but basically not acceptable...

                      I'll review this synchronisation issue in more detail to find solution that hopefully does not compromise performance.

                      • 8. Re: ConcurrentModificationException in log.debug() statement
                        belaban

                        Would you be happy if the printXXX() and toString() methods would catch(Throwable) and not propagate it ?

                        Bela

                        • 9. Re: ConcurrentModificationException in log.debug() statement
                          starksm64

                          We cannot let logging introduce errant behavior. If the info required for logging cannot be obtained in a thread safe manner without undue performance impact, then we do need to guard against failures due to the unsafe access and catch the exception.

                          • 10. Re: ConcurrentModificationException in log.debug() statement
                            norbert

                            I'd suggest to make use of the oswego concurrent library instead of using simple synchronisation.

                            e.g. use EDU.oswego.cs.dl.util.concurrent.ConcurrentReaderHashMap instead of HashMap....

                            this will both:

                            - enshure we use the 'best-of-breed' solution for concurrent access
                            - be as close as possible to the upcomming JDK 5.0 that includes the java.util.concurrent classes based on the oswego-library.

                            • 11. Re: ConcurrentModificationException in log.debug() statement
                              belaban

                              I put this on the roadmap