hazelcast/hazelcast — pull request #3717 by serkan-ozal (2014-09-29 06:23:59+00:00)
Title: Fix/master/issue 3659

There is a race condition on instance of **"com.hazelcast.query.impl.IndexImpl"**.
Here is an output of problematic execution:

The numeric values are **"System.nanoTime()"** while executing and outputs are sorted as their execution time values.
~~~~
saveEntryIndex start @child.child.timestamp: 1411908882507267000
saveEntryIndex end @child.child.timestamp: 1411908882507547000
saveEntryIndex start @child.child.timestamp: 1411908882513570000
getSubRecords start @child.child.timestamp: 1411908882513643000
getSubRecords start @child.child.timestamp: 1411908882513871000
getSubRecords end @child.child.timestamp: 1411908882513918000
saveEntryIndex end @child.child.timestamp: 1411908882513980000
getSubRecords end @child.child.timestamp: 1411908882514285000
saveEntryIndex start @child.child.timestamp: 1411908882523883000
saveEntryIndex end @child.child.timestamp: 1411908882524014000
~~~~

At first, I think that for just only **Put** operations on 2 nodes, there must be 2 **"saveEntryIndex start/end"** log and 2 **"getSubRecords start/end"** log. But there is one extra **"saveEntryIndex start/end"** log. Then I debugged the code and I found that that extra **"saveEntryIndex start/end"** log comes from execution of **"PromoteFromBackupOperation"** which is executed on backup node and calls **"saveEntryIndex"** method also.

As seen from logs, while executing **"saveEntryIndex"**, there is another call method of **"getSubRecords"** on same **"com.hazelcast.query.impl.IndexImpl"** instance. This means, before **"saveEntryIndex"** method execution is finished, there is another concurrent **"getSubRecords"** execution on same instance.

As seen from the line **97** of **"com.hazelcast.query.impl.IndexImpl"** class,
https://github.com/hazelcast/hazelcast/blob/master/hazelcast/src/main/java/com/hazelcast/query/impl/IndexImpl.java#L97

While adding new index entry, if index entry is updated, at first it is removed from the index store and then added to index store back with new value. If query come at this time (after remove but before add again), it can't find the record since that record is temporary removed before adding again with new value for update. I think, this case also explains why **"assertTrueEventually"** passes and **"assertTrue"** doesn't passes sometimes. And also explaing why this error doesn't occur on just single instance since there is no **"PromoteFromBackupOperation"** on just a single node and race condition on **"com.hazelcast.query.impl.IndexImpl"** doesn't happen.

So therefore, simply making all methods (or used from outside of this class) **synchronized**, solves the problem but making all methods **synchronized** is not a good solution because in that case query operations blocks each other but they can be executed in parallel since they just do read operation on index store. So for making less blocked operation, sync, read and write locks are used on index store.