-
Bug
-
Resolution: Cannot Reproduce
-
Critical
-
6.0.0.Final
Hi,
this issue is related to the ISPN-3090, but I thought to specify this case separately for bringing detailed explanation for the configuration and thrown exceptions.
The issue relates to the performance tests for Index enabled Infinispan cache, with configured Infinispan directory and Async JDBC. String Based Cache store.
The tests are running on 4 nodes and performing puts/gets on all nodes with many threads.
The problem is that, during data put, the following exceptions are thrown continuously:
04:04:05,633 ERROR [org.hibernate.search.exception.impl.LogErrorHandler] (Hibernate Search: Index updates queue processor for index query-1) HSEARCH000058: Exception occurred org.apache.lucene.index.IndexNotFoundException: no segments* file found in InfinispanDirectory{indexName='query'}: files: [] Primary Failure: Entity org.radargun.cachewrappers.InfinispanQueryWrapper$QueryableData Id S:_InstallBenchmarkStage_0 Work Type org.hibernate.search.backend.UpdateLuceneWork org.apache.lucene.index.IndexNotFoundException: no segments* file found in InfinispanDirectory{indexName='query'}: files: [] at org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfos.java:667) at org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfos.java:554) at org.apache.lucene.index.SegmentInfos.read(SegmentInfos.java:359) at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1138) at org.hibernate.search.backend.impl.lucene.IndexWriterHolder.createNewIndexWriter(IndexWriterHolder.java:148) at org.hibernate.search.backend.impl.lucene.IndexWriterHolder.getIndexWriter(IndexWriterHolder.java:115) at org.hibernate.search.backend.impl.lucene.AbstractWorkspaceImpl.getIndexWriter(AbstractWorkspaceImpl.java:117) at org.hibernate.search.backend.impl.lucene.LuceneBackendQueueTask.applyUpdates(LuceneBackendQueueTask.java:101) at org.hibernate.search.backend.impl.lucene.LuceneBackendQueueTask.run(LuceneBackendQueueTask.java:67) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) at java.util.concurrent.FutureTask.run(FutureTask.java:166) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:724) ...... 04:14:21,605 ERROR [org.hibernate.search.exception.impl.LogErrorHandler] (Hibernate Search: Index updates queue processor for index query-1) HSEARCH000058: Exception occurred org.apache.lucene.index.IndexNotFoundException: no segments* file found in InfinispanDirectory{indexName='query'}: files: [] Primary Failure: Entity org.radargun.cachewrappers.InfinispanQueryWrapper$QueryableData Id S:key_0_0_0000000000000017 Work Type org.hibernate.search.backend.UpdateLuceneWork org.apache.lucene.index.IndexNotFoundException: no segments* file found in InfinispanDirectory{indexName='query'}: files: [] at org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfos.java:667) at org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfos.java:554) at org.apache.lucene.index.SegmentInfos.read(SegmentInfos.java:359) at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1138) at org.hibernate.search.backend.impl.lucene.IndexWriterHolder.createNewIndexWriter(IndexWriterHolder.java:148) at org.hibernate.search.backend.impl.lucene.IndexWriterHolder.getIndexWriter(IndexWriterHolder.java:115) at org.hibernate.search.backend.impl.lucene.AbstractWorkspaceImpl.getIndexWriter(AbstractWorkspaceImpl.java:117) at org.hibernate.search.backend.impl.lucene.LuceneBackendQueueTask.applyUpdates(LuceneBackendQueueTask.java:101) at org.hibernate.search.backend.impl.lucene.LuceneBackendQueueTask.run(LuceneBackendQueueTask.java:67) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) at java.util.concurrent.FutureTask.run(FutureTask.java:166) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:724)
You can find the cache configuration attached.
Yet another thing to mention:
if the following line is added to the cache configuration:
<property name="default.indexmanager" value="org.infinispan.query.indexmanager.InfinispanIndexManager" />
then the issue is gone - no lock issue appears then.
[ISPN-3432] Data put to index enabled cache with Infinispan Directory provider using Async. JDBC StringBased CacheStore fails
Adrian Nistor (Inactive)
added a comment - This should be validated by QE by running radargun suite https://jenkins.mw.lab.eng.bos.redhat.com/hudson/view/JDG/view/PERF-LIB/job/jdg-radargun-clustered-query/ with Anna's config (file is attached) + the necessary fixes to make the config 6.0.Final compatible (replace <loaders> with <persistence>).
Adrian Nistor (Inactive)
added a comment - This should be validated by QE by running radargun suite https://jenkins.mw.lab.eng.bos.redhat.com/hudson/view/JDG/view/PERF-LIB/job/jdg-radargun-clustered-query/ with Anna's config (file is attached) + the necessary fixes to make the config 6.0.Final compatible (replace <loaders> with <persistence>). Adrian Nistor (Inactive)
added a comment - There's also Anna's comment that by adding InfinispanIndexManager the locking issue disappears. I think using InfinispanIndexManager is the normal case. The other might just work, but there are no guarantees.
Adrian Nistor (Inactive)
added a comment - There's also Anna's comment that by adding InfinispanIndexManager the locking issue disappears. I think using InfinispanIndexManager is the normal case. The other might just work, but there are no guarantees. Adrian Nistor (Inactive)
added a comment - There are two problems here:
#1 I re-analyzed the bug and it seems the myriad of "org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after..." were fixed some time ago by ISPN-2815. This can be confirmed by reverting the commit for ISPN-2815 from master; then we get lots of lock acquire exceptions. When running on latest master they no longer appear.
#2 The attached config contains a major problem with the jdbc config. Each of the 4 nodes has 3 cachestores that all write in the same h2 database. This leads to lots of:
2013-12-02 10:01:58,094 ERROR [JdbcStringBasedStore] (AsyncStoreProcessor-LuceneIndexesData_custom-6) ISPN008024: Error while storing string key to database; key: 'segments_3|0|16384|person' org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "PRIMARY_KEY_7 ON PUBLIC.""ISPN_STRING_TABLE_LuceneIndexesData_custom""(ID_COLUMN)"; SQL statement: INSERT INTO "ISPN_STRING_TABLE_LuceneIndexesData_custom" (DATA_COLUMN, TIMESTAMP_COLUMN, ID_COLUMN) VALUES(?,?,?) [23505-166] at org.h2.message.DbException.getJdbcSQLException(DbException.java:329) at org.h2.message.DbException.get(DbException.java:169) at org.h2.message.DbException.get(DbException.java:146) at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:81) at org.h2.index.TreeIndex.add(TreeIndex.java:62) at org.h2.table.RegularTable.addRow(RegularTable.java:121) at org.h2.command.dml.Insert.insertRows(Insert.java:124) at org.h2.command.dml.Insert.update(Insert.java:84) at org.h2.command.CommandContainer.update(CommandContainer.java:73) at org.h2.command.Command.executeUpdate(Command.java:226) at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:143) at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:129) at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:105) at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore.write(JdbcStringBasedStore.java:166) at org.infinispan.persistence.async.AsyncCacheWriter.applyModificationsSync(AsyncCacheWriter.java:154) at org.infinispan.persistence.async.AsyncCacheWriter$AsyncStoreProcessor.retryWork(AsyncCacheWriter.java:329) at org.infinispan.persistence.async.AsyncCacheWriter$AsyncStoreProcessor.run(AsyncCacheWriter.java:313) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:724)
and
2013-12-02 10:02:01,890 ERROR [JdbcStringBasedStore] (persistence-thread-0,NodeJ) ISPN008007: SQL error while fetching all StoredEntries
org.h2.jdbc.JdbcSQLException: Table "ISPN_STRING_TABLE_LuceneIndexesMetadata_custom" not found; SQL statement:
SELECT DATA_COLUMN,ID_COLUMN, TIMESTAMP_COLUMN FROM "ISPN_STRING_TABLE_LuceneIndexesMetadata_custom" WHERE TIMESTAMP_COLUMN > ? OR TIMESTAMP_COLUMN < 0 [42102-166]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:329)
at org.h2.message.DbException.get(DbException.java:169)
at org.h2.message.DbException.get(DbException.java:146)
at org.h2.command.Parser.readTableOrView(Parser.java:4757)
at org.h2.command.Parser.readTableFilter(Parser.java:1084)
at org.h2.command.Parser.parseSelectSimpleFromPart(Parser.java:1690)
at org.h2.command.Parser.parseSelectSimple(Parser.java:1797)
at org.h2.command.Parser.parseSelectSub(Parser.java:1684)
at org.h2.command.Parser.parseSelectUnion(Parser.java:1527)
at org.h2.command.Parser.parseSelect(Parser.java:1515)
at org.h2.command.Parser.parsePrepared(Parser.java:405)
at org.h2.command.Parser.parse(Parser.java:279)
at org.h2.command.Parser.parse(Parser.java:251)
at org.h2.command.Parser.prepareCommand(Parser.java:217)
at org.h2.engine.Session.prepareLocal(Session.java:415)
at org.h2.engine.Session.prepareCommand(Session.java:364)
at org.h2.jdbc.JdbcConnection.prepareCommand(JdbcConnection.java:1111)
at org.h2.jdbc.JdbcPreparedStatement.<init>(JdbcPreparedStatement.java:71)
at org.h2.jdbc.JdbcConnection.prepareStatement(JdbcConnection.java:266)
at com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:213)
at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore$2.call(JdbcStringBasedStore.java:321)
at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore$2.call(JdbcStringBasedStore.java:309)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
...
The 4 nodes should not share the database in this case. By giving each node's database a unique name (instead of all being connectionUrl="jdbc:h2:mem:infinispan_string_based") the above jdbc errors disappear.
Since Anna supplied a config file by node java code, I've tested this using a variation of ClusteredCacheWithAsyncDirTest and then DistributedMassIndexingTest with the supplied config.
Please note these tests do not use multiple threads to cause the errors. Just one thread is enough to trigger the exceptions I mentioned.
I can no longer access the log file mentioned: https://jenkins.mw.lab.eng.bos.redhat.com/hudson/view/JDG/view/PERF-LIB/job/jdg-radargun-clustered-query/128/console-edg-perf10/
I think this issue can be closed as a consequence of ISPN-2815, but before doing so it would be good to run the radargun "performance tests for Index enabled Infinispan cache" Anna mentioned just to make sure the no problems surface under bigger load.
Adrian Nistor (Inactive)
added a comment - There are two problems here:
#1 I re-analyzed the bug and it seems the myriad of "org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after..." were fixed some time ago by ISPN-2815 . This can be confirmed by reverting the commit for ISPN-2815 from master; then we get lots of lock acquire exceptions. When running on latest master they no longer appear.
#2 The attached config contains a major problem with the jdbc config. Each of the 4 nodes has 3 cachestores that all write in the same h2 database. This leads to lots of:
2013-12-02 10:01:58,094 ERROR [JdbcStringBasedStore] (AsyncStoreProcessor-LuceneIndexesData_custom-6) ISPN008024: Error while storing string key to database; key: 'segments_3|0|16384|person'
org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "PRIMARY_KEY_7 ON PUBLIC.""ISPN_STRING_TABLE_LuceneIndexesData_custom""(ID_COLUMN)"; SQL statement:
INSERT INTO "ISPN_STRING_TABLE_LuceneIndexesData_custom" (DATA_COLUMN, TIMESTAMP_COLUMN, ID_COLUMN) VALUES(?,?,?) [23505-166]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:329)
at org.h2.message.DbException.get(DbException.java:169)
at org.h2.message.DbException.get(DbException.java:146)
at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:81)
at org.h2.index.TreeIndex.add(TreeIndex.java:62)
at org.h2.table.RegularTable.addRow(RegularTable.java:121)
at org.h2.command.dml.Insert.insertRows(Insert.java:124)
at org.h2.command.dml.Insert.update(Insert.java:84)
at org.h2.command.CommandContainer.update(CommandContainer.java:73)
at org.h2.command.Command.executeUpdate(Command.java:226)
at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:143)
at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:129)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:105)
at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore.write(JdbcStringBasedStore.java:166)
at org.infinispan.persistence.async.AsyncCacheWriter.applyModificationsSync(AsyncCacheWriter.java:154)
at org.infinispan.persistence.async.AsyncCacheWriter$AsyncStoreProcessor.retryWork(AsyncCacheWriter.java:329)
at org.infinispan.persistence.async.AsyncCacheWriter$AsyncStoreProcessor.run(AsyncCacheWriter.java:313)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:724)
and
2013-12-02 10:02:01,890 ERROR [JdbcStringBasedStore] (persistence-thread-0,NodeJ) ISPN008007: SQL error while fetching all StoredEntries
org.h2.jdbc.JdbcSQLException: Table "ISPN_STRING_TABLE_LuceneIndexesMetadata_custom" not found; SQL statement:
SELECT DATA_COLUMN,ID_COLUMN, TIMESTAMP_COLUMN FROM "ISPN_STRING_TABLE_LuceneIndexesMetadata_custom" WHERE TIMESTAMP_COLUMN > ? OR TIMESTAMP_COLUMN < 0 [42102-166]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:329)
at org.h2.message.DbException.get(DbException.java:169)
at org.h2.message.DbException.get(DbException.java:146)
at org.h2.command.Parser.readTableOrView(Parser.java:4757)
at org.h2.command.Parser.readTableFilter(Parser.java:1084)
at org.h2.command.Parser.parseSelectSimpleFromPart(Parser.java:1690)
at org.h2.command.Parser.parseSelectSimple(Parser.java:1797)
at org.h2.command.Parser.parseSelectSub(Parser.java:1684)
at org.h2.command.Parser.parseSelectUnion(Parser.java:1527)
at org.h2.command.Parser.parseSelect(Parser.java:1515)
at org.h2.command.Parser.parsePrepared(Parser.java:405)
at org.h2.command.Parser.parse(Parser.java:279)
at org.h2.command.Parser.parse(Parser.java:251)
at org.h2.command.Parser.prepareCommand(Parser.java:217)
at org.h2.engine.Session.prepareLocal(Session.java:415)
at org.h2.engine.Session.prepareCommand(Session.java:364)
at org.h2.jdbc.JdbcConnection.prepareCommand(JdbcConnection.java:1111)
at org.h2.jdbc.JdbcPreparedStatement.<init>(JdbcPreparedStatement.java:71)
at org.h2.jdbc.JdbcConnection.prepareStatement(JdbcConnection.java:266)
at com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:213)
at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore$2.call(JdbcStringBasedStore.java:321)
at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore$2.call(JdbcStringBasedStore.java:309)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
...
The 4 nodes should not share the database in this case. By giving each node's database a unique name (instead of all being connectionUrl="jdbc:h2:mem:infinispan_string_based") the above jdbc errors disappear.
Since Anna supplied a config file by node java code, I've tested this using a variation of ClusteredCacheWithAsyncDirTest and then DistributedMassIndexingTest with the supplied config.
Please note these tests do not use multiple threads to cause the errors. Just one thread is enough to trigger the exceptions I mentioned.
I can no longer access the log file mentioned: https://jenkins.mw.lab.eng.bos.redhat.com/hudson/view/JDG/view/PERF-LIB/job/jdg-radargun-clustered-query/128/console-edg-perf10/
I think this issue can be closed as a consequence of ISPN-2815 , but before doing so it would be good to run the radargun "performance tests for Index enabled Infinispan cache" Anna mentioned just to make sure the no problems surface under bigger load. 
Martin Gencur <mgencur@redhat.com> changed the Status of bug 1024936 from NEW to CLOSED