Got LockObtainFailedException error under heavy load

[dungleonhart]

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.

[dungleonhart]

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,

[sannegrinovero]

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.

[dungleonhart]

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,