3 Replies Latest reply on Dec 30, 2011 8:40 AM by Dzung Leonhart

    Got LockObtainFailedException error under heavy load

    Dzung Leonhart Newbie

      Hi,

       

      I'm using Hibernate Search with Infinispan and JGroups in my project. When doing load testing (about several hundred requests within 10 seconds) with 2 nodes (same configurations), I found some errors and tried to apply a few tunning tips like:

           - Increase the lock & replication timeout (to 120000)

           - Set useLockStriping=false and increase the concurrencyLevel (to 5000)

           - Modify rmem_max & wmem_max of Linux.

           - Use distribution mode instead of replication mode

       

      But poor me, I still got these logs (2 nodes):

       

      Node 1:

      2011-12-29 15:17:57,731 [Hibernate Search: Directory writer-1] ERROR org.hibernate.search.exception.impl.LogErrorHandler - Exception occurred org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: org.infinispan.lucene.locking.BaseLuceneLock@13782ef

      Primary Failure:

          Entity tc.model.TestCase  Id 10144  Work Type  org.hibernate.search.backend.AddLuceneWork

       

      org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: org.infinispan.lucene.locking.BaseLuceneLock@13782ef

          at org.apache.lucene.store.Lock.obtain(Lock.java:84)

          at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1097)

          at org.hibernate.search.backend.Workspace.createNewIndexWriter(Workspace.java:202)

          at org.hibernate.search.backend.Workspace.getIndexWriter(Workspace.java:180)

          at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:103)

          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

          at java.lang.Thread.run(Thread.java:662)

      2011-12-29 15:17:57,731 [Hibernate Search: Directory writer-1] ERROR org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor - Unexpected error in Lucene Backend:

      java.lang.NullPointerException

          at org.hibernate.search.backend.impl.lucene.works.AddWorkDelegate.performWork(AddWorkDelegate.java:76)

          at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:106)

          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

          at java.lang.Thread.run(Thread.java:662)

      2011-12-29 15:17:57,731 [Hibernate Search: Directory writer-1] ERROR org.hibernate.search.exception.impl.LogErrorHandler - Exception occurred java.lang.NullPointerException

      Primary Failure:

          Entity tc.model.TestCase  Id 10144  Work Type  org.hibernate.search.backend.AddLuceneWork

       

      java.lang.NullPointerException

          at org.hibernate.search.backend.impl.lucene.works.AddWorkDelegate.performWork(AddWorkDelegate.java:76)

          at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:106)

          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

          at java.lang.Thread.run(Thread.java:662)

      2011-12-29 15:18:00,308 [Hibernate Search: Directory writer-1] ERROR org.hibernate.search.exception.impl.LogErrorHandler - Exception occurred org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: org.infinispan.lucene.locking.BaseLuceneLock@13782ef

      Primary Failure:

          Entity tc.model.TestCase  Id 10145  Work Type  org.hibernate.search.backend.AddLuceneWork

       

      org.apache.lucene.store.LockObtainFailedException: Lock obtain timed out: org.infinispan.lucene.locking.BaseLuceneLock@13782ef

          at org.apache.lucene.store.Lock.obtain(Lock.java:84)

          at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1097)

          at org.hibernate.search.backend.Workspace.createNewIndexWriter(Workspace.java:202)

          at org.hibernate.search.backend.Workspace.getIndexWriter(Workspace.java:180)

          at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:103)

          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

          at java.lang.Thread.run(Thread.java:662)

      2011-12-29 15:18:00,308 [Hibernate Search: Directory writer-1] ERROR org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor - Unexpected error in Lucene Backend:

      java.lang.NullPointerException

          at org.hibernate.search.backend.impl.lucene.works.AddWorkDelegate.performWork(AddWorkDelegate.java:76)

          at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:106)

          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

          at java.lang.Thread.run(Thread.java:662)

      2011-12-29 15:18:00,309 [Hibernate Search: Directory writer-1] ERROR org.hibernate.search.exception.impl.LogErrorHandler - Exception occurred java.lang.NullPointerException

      Primary Failure:

          Entity tc.model.TestCase  Id 10145  Work Type  org.hibernate.search.backend.AddLuceneWork

       

      java.lang.NullPointerException

          at org.hibernate.search.backend.impl.lucene.works.AddWorkDelegate.performWork(AddWorkDelegate.java:76)

          at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:106)

          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

          at java.lang.Thread.run(Thread.java:662)

      ...

      ---------------------------

       

      Node 2:

      2011-12-29 15:18:00,353 [Hibernate Search: Directory writer-1] ERROR org.hibernate.search.exception.impl.LogErrorHandler - Exception occurred java.io.FileNotFoundException: Error loading medatada for index file: _b1.cfs|M|tc.model.TestCase

      Primary Failure:

          Entity tc.model.TestCase  Id 10099  Work Type  org.hibernate.search.backend.AddLuceneWork

       

      java.io.FileNotFoundException: Error loading medatada for index file: _b1.cfs|M|tc.model.TestCase

          at org.infinispan.lucene.InfinispanDirectory.openInput(InfinispanDirectory.java:300)

          at org.apache.lucene.store.Directory.openInput(Directory.java:139)

          at org.apache.lucene.index.CompoundFileReader.<init>(CompoundFileReader.java:66)

          at org.apache.lucene.index.CompoundFileReader.<init>(CompoundFileReader.java:55)

          at org.apache.lucene.index.IndexWriter.getFieldInfos(IndexWriter.java:1193)

          at org.apache.lucene.index.IndexWriter.getCurrentFieldInfos(IndexWriter.java:1213)

          at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1149)

          at org.hibernate.search.backend.Workspace.createNewIndexWriter(Workspace.java:202)

          at org.hibernate.search.backend.Workspace.getIndexWriter(Workspace.java:180)

          at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:103)

          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

          at java.lang.Thread.run(Thread.java:662)

      2011-12-29 15:18:00,355 [Hibernate Search: Directory writer-1] ERROR org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor - Unexpected error in Lucene Backend:

      java.lang.NullPointerException

          at org.hibernate.search.backend.impl.lucene.works.AddWorkDelegate.performWork(AddWorkDelegate.java:76)

          at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:106)

          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

          at java.lang.Thread.run(Thread.java:662)

      2011-12-29 15:18:00,355 [Hibernate Search: Directory writer-1] ERROR org.hibernate.search.exception.impl.LogErrorHandler - Exception occurred java.lang.NullPointerException

      Primary Failure:

          Entity tc.model.TestCase  Id 10099  Work Type  org.hibernate.search.backend.AddLuceneWork

       

      java.lang.NullPointerException

          at org.hibernate.search.backend.impl.lucene.works.AddWorkDelegate.performWork(AddWorkDelegate.java:76)

          at org.hibernate.search.backend.impl.lucene.PerDPQueueProcessor.run(PerDPQueueProcessor.java:106)

          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

          at java.lang.Thread.run(Thread.java:662)

      ...

      --------------------------

       

      Here're my configurations:

       

        1. Jars:

                * hibernate-search-3.4.1.Final.jar

                * hibernate-search-infinispan-3.4.1.Final.jar

                * infinispan-core-4.2.1.FINAL.jar

                * infinispan-lucene-directory-4.2.1.FINAL.jar

                * jgroups-2.11.1.Final.jar

       

           2. Hibernate:      

                     <bean id="sessionFactory" class="org.springframework.orm.hibernate3.annotation.AnnotationSessionFactoryBean">

                          <property name="hibernateProperties">

                               <props>

                                     <prop key="hibernate.dialect">org.hibernate.dialect.MySQLDialect</prop>

                                     <prop key="hibernate.search.default.directory_provider">infinispan</prop>

                                     <prop key="hibernate.search.infinispan.configuration_resourcename">hibernate-search-infinispan.xml</prop>

                                     <prop key="hibernate.search.worker.backend">jgroupsMaster</prop>

                                 <prop key="hibernate.search.worker.execution">async</prop>

                               </props>

                          </property>

                     </bean>

       

           3. Configuration files: hibernate-search-infinispan.xml & jdbc_ping.xml (please find them in the attachments)

       

      Please give me some advices to overcome this problem.

      By the way, I just think that the Master/Slave model can fix this issue since the Master node is the only one who takes care of the indexed data. (Am I correct?). But I'm having difficulty in configuring that model (as I wrote in this thread http://community.jboss.org/message/643577#643577).

       

      Thanks a lot, Infinispan team. You're all great guys.

        • 1. Re: Got LockObtainFailedException error under heavy load
          Dzung Leonhart Newbie

          Hi,

           

          One more thing that I've suspected that: when I put 2 nodes on my local machine (2 Tomcat servers), it works as expected. I wonder it might only work well in environments that allow multicast?

           

          Best Regards,

          • 2. Re: Got LockObtainFailedException error under heavy load
            Sanne Grinovero Master

            Hi,

            the LockObtainFailedException is a problem you would have as well if you where using a filesystem to store the Lucene index: unfortunately Lucene expects a single IndexWriter instance on its index, and so Lucene locks the index when an IndexWriter is opened and unlocks it when it's released; the problem is that when the index is locked by IndexWriter A, and IndexWriter B wants to open it, B won't wait as you would expect with a Java lock but will give it a couple of temtatives and then fail throwing the exception you see.

             

            So if you are sharing a local filesystem index directory among two Hibernate Search applications on the same machine, you would have the same issue, you would need to make sure that only one node writes to it at the same time.

            Since Lucene will give it a couple of temtatives before failing, if you don't have an high load with some luck the exception won't happen, but load test doing write operations will get you in trouble.

             

            When clustering the index among multiple machines (nodes), you have the same issue, so indeed you should use the Master/Slave approach from Hibernate Search, using either the JGroups backend or the JMS backend; you can safely avoid the master/slave only if you know that only one node is writing, or if write operation are not frequent, so that it's very unlikely two nodes would attempt to write at the same time.

             

            I don't know how starting it in two Tomcat servers on the same node helps.. are you sure they are clustered?

            I'm going to read your other thread as well.

            1 of 1 people found this helpful
            • 3. Re: Got LockObtainFailedException error under heavy load
              Dzung Leonhart Newbie

              Hi Sanne,

               

              It was really my mistake, my second post should be in a different thread (Problem with jgroupsSlavebackend).

              Sorry so much for that, and also thanks a lot for your helpful answer.

               

              Best Regards,