[
https://issues.apache.org/jira/browse/JENA-131?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13145295#comment-13145295
]
Andy Seaborne commented on JENA-131:
------------------------------------
The debugging code shows something going wrong - exactly what isn't completely
clear to me yet.
I get output from T_TransSystem but in every case the transactions detected are
READ transactions acting over a WRITE transaction that has not been flushed to
the main DB yet.
I only see errors after several iterations of the tests -- I think this is
because the JIT runs and, because the code has no locking, the issue of where
the concurrency barriers mean fields are updated matters. That said, it is
finding different threads which needs explaining and fixing.
> TxTDB problem during concurrent execution
> -----------------------------------------
>
> Key: JENA-131
> URL: https://issues.apache.org/jira/browse/JENA-131
> Project: Jena
> Issue Type: Bug
> Components: TDB
> Environment: arq-2.8.9-20111001.145524-39 and
> tx-tdb-0.9.0-20111006.082548-13 on IBM JRE 6
> Reporter: Simon Helsen
> Attachments: patch.txt, patch.txt
>
>
> In a massive concurrent test with many reads and writes, I am running into
> the problems shown below. I suspect the problem only occurs if a read and
> write are trying to operate on the same data at the same time, i.e. the
> transactions don't isolate enough. My test case is inside the framework. I
> currently have no test case for you to try, but I am hoping you can see
> something by inspecting the stack trace
> ModelWriteActivity: 1579ms
> 17:46:27,183 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterConcat/55657
> 17:46:27,254 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterSingleton/55658
> 17:46:27,257 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterPeek/55659
> 17:46:27,261 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterTDB/55660
> 17:46:27,264 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterOptionalIndex/55661
> 17:46:27,335 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterOptionalIndex/55662
> 17:46:27,338 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterDefaulting/55803
> 17:46:27,395 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterDefaulting/55807
> 17:46:27,399 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterPeek/55808
> 17:46:27,403 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterTDB/55809
> 17:46:27,406 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterAssign/55810
> 17:46:27,410 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterSingleton/55811
> 17:46:27,490 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterPeek/55812
> 17:46:27,493 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterTDB/55813
> 17:46:27,497 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterOptionalIndex/55814
> 17:46:27,502 [1948218399@qtp-533667791-14] WARN
> hpl.jena.sparql.engine.iterator.QueryIteratorCheck - Open iterator:
> QueryIterOptionalIndex/55815
> 17:46:27,507 [1948218399@qtp-533667791-14] ERROR com.ibm.team.jfs
> - Originating Exception:
> java.lang.IndexOutOfBoundsException: Index: 20, Size: 18
> at java.util.ArrayList.remove(ArrayList.java:552)
> at java.util.ArrayList.remove(ArrayList.java:572)
> at
> com.hp.hpl.jena.tdb.transaction.Transaction.removeIterator(Transaction.java:188)
> at
> com.hp.hpl.jena.tdb.transaction.BlockMgrJournal.endIterator(BlockMgrJournal.java:312)
> at
> com.hp.hpl.jena.tdb.transaction.BlockMgrJournal.endIterator(BlockMgrJournal.java:313)
> at
> com.hp.hpl.jena.tdb.base.block.BlockMgrWrapper.endIterator(BlockMgrWrapper.java:134)
> at
> com.hp.hpl.jena.tdb.base.recordbuffer.RecordRangeIterator.close(RecordRangeIterator.java:155)
> at
> com.hp.hpl.jena.tdb.base.recordbuffer.RecordRangeIterator.hasNext(RecordRangeIterator.java:112)
> at org.openjena.atlas.iterator.Iter$4.hasNext(Iter.java:274)
> at
> com.hp.hpl.jena.tdb.sys.DatasetControlMRSW$IteratorCheckNotConcurrent.hasNext(DatasetControlMRSW.java:119)
> at org.openjena.atlas.iterator.Iter$3.hasNext(Iter.java:164)
> at org.openjena.atlas.iterator.Iter$6.hasNext(Iter.java:359)
> at org.openjena.atlas.iterator.Iter$3.hasNext(Iter.java:164)
> at org.openjena.atlas.iterator.Iter$4.hasNext(Iter.java:274)
> at org.openjena.atlas.iterator.Iter$3.hasNext(Iter.java:164)
> at org.openjena.atlas.iterator.Iter.hasNext(Iter.java:742)
> at
> org.openjena.atlas.iterator.RepeatApplyIterator.hasNext(RepeatApplyIterator.java:58)
> at
> org.openjena.atlas.iterator.RepeatApplyIterator.hasNext(RepeatApplyIterator.java:46)
> at
> org.openjena.atlas.iterator.RepeatApplyIterator.hasNext(RepeatApplyIterator.java:46)
> at
> org.openjena.atlas.iterator.RepeatApplyIterator.hasNext(RepeatApplyIterator.java:46)
> at
> org.openjena.atlas.iterator.RepeatApplyIterator.hasNext(RepeatApplyIterator.java:46)
> at org.openjena.atlas.iterator.Iter$4.hasNext(Iter.java:274)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIterPlainWrapper.hasNextBinding(QueryIterPlainWrapper.java:54)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:107)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIterRepeatApply.makeNextStage(QueryIterRepeatApply.java:106)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIterRepeatApply.hasNextBinding(QueryIterRepeatApply.java:65)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:107)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIterRepeatApply.makeNextStage(QueryIterRepeatApply.java:106)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIterRepeatApply.hasNextBinding(QueryIterRepeatApply.java:65)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:107)
> at
> com.hp.hpl.jena.tdb.solver.OpExecutorTDB.optimizeExecuteQuads(OpExecutorTDB.java:215)
> at
> com.hp.hpl.jena.tdb.solver.OpExecutorTDB.execute(OpExecutorTDB.java:152)
> at
> com.hp.hpl.jena.sparql.engine.main.ExecutionDispatch.visit(ExecutionDispatch.java:63)
> at
> com.hp.hpl.jena.sparql.algebra.op.OpQuadPattern.visit(OpQuadPattern.java:97)
> at
> com.hp.hpl.jena.sparql.engine.main.ExecutionDispatch.exec(ExecutionDispatch.java:43)
> at
> com.hp.hpl.jena.sparql.engine.main.OpExecutor.executeOp(OpExecutor.java:119)
> at
> com.hp.hpl.jena.sparql.engine.main.OpExecutor.execute(OpExecutor.java:208)
> at
> com.hp.hpl.jena.sparql.engine.main.ExecutionDispatch.visit(ExecutionDispatch.java:105)
> at
> com.hp.hpl.jena.sparql.algebra.op.OpSequence.visit(OpSequence.java:73)
> at
> com.hp.hpl.jena.sparql.engine.main.ExecutionDispatch.exec(ExecutionDispatch.java:45)
> at
> com.hp.hpl.jena.sparql.engine.main.OpExecutor.executeOp(OpExecutor.java:119)
> at
> com.hp.hpl.jena.sparql.engine.main.OpExecutor.execute(OpExecutor.java:464)
> at
> com.hp.hpl.jena.sparql.engine.main.ExecutionDispatch.visit(ExecutionDispatch.java:246)
> at com.hp.hpl.jena.sparql.algebra.op.OpAssign.visit(OpAssign.java:116)
> at
> com.hp.hpl.jena.sparql.engine.main.ExecutionDispatch.exec(ExecutionDispatch.java:45)
> at
> com.hp.hpl.jena.sparql.engine.main.OpExecutor.executeOp(OpExecutor.java:119)
> at
> com.hp.hpl.jena.sparql.engine.main.OpExecutor.execute(OpExecutor.java:92)
> at com.hp.hpl.jena.sparql.engine.main.QC.execute(QC.java:52)
> at
> com.hp.hpl.jena.sparql.engine.main.iterator.QueryIterUnion.nextStage(QueryIterUnion.java:55)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIterRepeatApply.makeNextStage(QueryIterRepeatApply.java:113)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIterRepeatApply.hasNextBinding(QueryIterRepeatApply.java:65)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:107)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIterConvert.hasNextBinding(QueryIterConvert.java:65)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:107)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIterSlice.hasNextBinding(QueryIterSlice.java:76)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:107)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorWrapper.hasNextBinding(QueryIteratorWrapper.java:40)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:107)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorWrapper.hasNextBinding(QueryIteratorWrapper.java:40)
> at
> com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:107)
> at
> com.hp.hpl.jena.sparql.engine.ResultSetStream.hasNext(ResultSetStream.java:70)
> at
> com.hp.hpl.jena.sparql.engine.QueryExecutionBase.execDescribe(QueryExecutionBase.java:278)
> at
> com.hp.hpl.jena.sparql.engine.QueryExecutionBase.execDescribe(QueryExecutionBase.java:256)
> <snip>
> DataSetReadActivity: 1249ms
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators:
https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
