Adrian Nistor <anistor> made a comment on jira ISPN-3432

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:

{noformat}
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)
{noformat}

and

{noformat}
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)
        ...
{noformat}

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 <anistor> made a comment on jira ISPN-3432

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 <anistor> updated the status of jira ISPN-3432 to Closed

Adrian Nistor <anistor> made a comment on jira ISPN-3432

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>).

I executed the tests with updated configs and did not see the aforementioned exception.