Return-Path: X-Original-To: apmail-incubator-jena-dev-archive@minotaur.apache.org Delivered-To: apmail-incubator-jena-dev-archive@minotaur.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id B9EDF93C2 for ; Fri, 21 Oct 2011 09:32:55 +0000 (UTC) Received: (qmail 44198 invoked by uid 500); 21 Oct 2011 09:32:55 -0000 Delivered-To: apmail-incubator-jena-dev-archive@incubator.apache.org Received: (qmail 44124 invoked by uid 500); 21 Oct 2011 09:32:54 -0000 Mailing-List: contact jena-dev-help@incubator.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: jena-dev@incubator.apache.org Delivered-To: mailing list jena-dev@incubator.apache.org Received: (qmail 44115 invoked by uid 99); 21 Oct 2011 09:32:53 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 21 Oct 2011 09:32:53 +0000 X-ASF-Spam-Status: No, hits=-2000.5 required=5.0 tests=ALL_TRUSTED,RP_MATCHES_RCVD X-Spam-Check-By: apache.org Received: from [140.211.11.116] (HELO hel.zones.apache.org) (140.211.11.116) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 21 Oct 2011 09:32:51 +0000 Received: from hel.zones.apache.org (hel.zones.apache.org [140.211.11.116]) by hel.zones.apache.org (Postfix) with ESMTP id 8A5CA314B68 for ; Fri, 21 Oct 2011 09:30:32 +0000 (UTC) Date: Fri, 21 Oct 2011 09:30:32 +0000 (UTC) From: "Andy Seaborne (Commented) (JIRA)" To: jena-dev@incubator.apache.org Message-ID: <774732026.348.1319189432568.JavaMail.tomcat@hel.zones.apache.org> In-Reply-To: <1091076314.10217.1318025189972.JavaMail.tomcat@hel.zones.apache.org> Subject: [jira] [Commented] (JENA-131) TxTDB problem during concurrent execution MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/JENA-131?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13132546#comment-13132546 ] Andy Seaborne commented on JENA-131: ------------------------------------ Simon, I don't understand: """ Even without aborting queries, I run into the same issue. However, I looked at it more carefully. I think the problem is that in the class Transaction, the methods """ If a transaction is being used from only one thread (I think you have said this is your setup) then Transaction.addIterator and Transaction.removeIterator are called from that thread. As far as I can see, addIterator is only called from the query execution thread. removeIterator is called from RecordRangeIterator.close but the query abort mechanism is supposed to work by the abort setting flags in the query iterator structures and the clearup being done on the same thread as the query. If this isn't the case, then its' the close/abort code that's at fault. If there a CME stacktrace to show this invariant is being violated? Simon - has this (the initial report) been observed on an Oracle JRE? > 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 > Assignee: Paolo Castagna > Attachments: 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) > > 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