You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@jena.apache.org by Simon Helsen <sh...@ca.ibm.com> on 2012/08/22 00:32:21 UTC
something that was written in a transaction is not found
Hi,
I am not yet opening a bug because I don't have an isolated test case yet,
but within our own suite and product I am noticing that some data which is
written by a write transaction is not found via the read transaction (this
is all on 2.7.4 from HEAD -> I rebuild myself. We don't have this problem
with 2.7.1). I enabled transactional logging, and I am seeing for each
write transaction "Txn[8]/W: Add to pending queue". I assume this is ok?
17:44:05,327 [1889890469@qtp-1827958004-10] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[1]/R: begin$
17:44:05,334 [1889890469@qtp-1827958004-10] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[1]/R: start
17:44:05,437 [1889890469@qtp-1827958004-10] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[1]/R: finish
17:44:05,885 [1889890469@qtp-1827958004-10] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[2]/R: begin$
17:44:05,892 [1889890469@qtp-1827958004-10] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[2]/R: start
17:44:05,896 [1889890469@qtp-1827958004-10] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[2]/R: finish
17:44:05,899 [1889890469@qtp-1827958004-10] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[3]/R: begin$
17:44:05,901 [1889890469@qtp-1827958004-10] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[3]/R: start
17:44:05,905 [1889890469@qtp-1827958004-10] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[3]/R: finish
17:44:06,980 [1889890469@qtp-1827958004-10] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[4]/R: begin$
17:44:06,983 [1889890469@qtp-1827958004-10] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[4]/R: start
17:44:06,987 [1889890469@qtp-1827958004-10] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[4]/R: finish
17:44:08,304 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[5]/R: begin$
17:44:08,306 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[5]/R: start
17:44:08,323 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[5]/R: finish
17:44:08,326 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[6]/R: begin$
17:44:08,328 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[6]/R: start
17:44:08,333 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[6]/R: finish
17:44:08,335 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[7]/R: begin$
17:44:08,337 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[7]/R: start
17:44:08,343 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[7]/R: finish
17:44:08,347 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[8]/W: begin$
17:44:08,363 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[8]/W: begin
17:44:08,447 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[8]/W: commit
17:44:08,449 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[8]/W: Add to
pending queue
17:44:08,459 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[9]/W: begin$
17:44:08,463 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[9]/W: begin
17:44:08,517 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[9]/W: commit
17:44:08,519 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[9]/W: Add to
pending queue
17:44:18,636 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[10]/W: begin$
17:44:18,641 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[10]/W: begin
17:44:18,671 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[10]/W: commit
17:44:18,673 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[10]/W: Add to
pending queue
17:44:26,784 [638461454@qtp-1827958004-17] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[11]/R: begin$
17:44:26,787 [638461454@qtp-1827958004-17] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[11]/R: start
17:44:26,989 [638461454@qtp-1827958004-17] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[11]/R: finish
17:44:28,608 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[12]/R: begin$
17:44:28,611 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[12]/R: start
17:44:28,616 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[12]/R: finish
17:44:28,619 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[13]/R: begin$
17:44:28,620 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[13]/R: start
17:44:28,633 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[13]/R: finish
17:44:28,636 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[14]/R: begin$
17:44:28,638 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[14]/R: start
17:44:28,643 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[14]/R: finish
17:44:28,650 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[15]/W: begin$
17:44:28,653 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[15]/W: begin
17:44:28,672 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[15]/W: commit
17:44:28,675 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[15]/W: Add to
pending queue
17:44:28,688 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[16]/W: begin$
17:44:28,692 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[16]/W: begin
17:44:28,785 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[16]/W: commit
17:44:28,788 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[16]/W: Add to
pending queue
17:44:29,099 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[17]/R: begin$
17:44:29,102 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[17]/R: start
17:44:29,108 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[17]/R: finish
17:44:29,110 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[18]/R: begin$
17:44:29,112 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[18]/R: start
17:44:29,117 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[18]/R: finish
17:44:29,120 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[19]/R: begin$
17:44:29,122 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[19]/R: start
17:44:29,127 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[19]/R: finish
17:44:29,132 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[20]/W: begin$
17:44:29,136 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[20]/W: begin
17:44:29,230 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[20]/W: commit
17:44:29,232 [jazz.jfs.indexer.internal.triple] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[20]/W: Add to
pending queue
17:44:29,683 [638461454@qtp-1827958004-17] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[21]/R: begin$
17:44:29,686 [638461454@qtp-1827958004-17] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[21]/R: start
17:44:29,693 [638461454@qtp-1827958004-17] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[21]/R: finish
Then, when I kill the process and start again, I have the following
sequence, leading to the Quad: predicate cannot be null
17:49:59,611 [678045802@qtp-316412636-5] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[1]/R: begin$
17:49:59,617 [678045802@qtp-316412636-5] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[1]/R: start
17:49:59,766 [678045802@qtp-316412636-5] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[1]/R: finish
17:49:59,810 [678045802@qtp-316412636-5] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[2]/R: begin$
17:49:59,813 [678045802@qtp-316412636-5] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[2]/R: start
17:49:59,818 [678045802@qtp-316412636-5] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[2]/R: finish
17:49:59,832 [678045802@qtp-316412636-5] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[3]/R: begin$
17:49:59,844 [678045802@qtp-316412636-5] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[3]/R: start
17:49:59,850 [678045802@qtp-316412636-5] ERROR com.ibm.team.jfs -
@ID@E An unexpected problem occurred while processing a transactional
model read activity
java.lang.UnsupportedOperationException: Quad: predicate cannot be null
at com.hp.hpl.jena.sparql.core.Quad.<init>(Quad.java:61)
at com.hp.hpl.jena.tdb.lib.TupleLib.quad(TupleLib.java:162)
at com.hp.hpl.jena.tdb.lib.TupleLib.quad(TupleLib.java:153)
at com.hp.hpl.jena.tdb.lib.TupleLib.access$100(TupleLib.java:45)
at com.hp.hpl.jena.tdb.lib.TupleLib$4.convert(TupleLib.java:87)
at com.hp.hpl.jena.tdb.lib.TupleLib$4.convert(TupleLib.java:83)
at org.openjena.atlas.iterator.Iter$4.next(Iter.java:301)
at
com.hp.hpl.jena.tdb.store.GraphTDBBase$ProjectQuadsToTriples.next(GraphTDBBase.java:178)
at
com.hp.hpl.jena.tdb.store.GraphTDBBase$ProjectQuadsToTriples.next(GraphTDBBase.java:166)
at
com.hp.hpl.jena.util.iterator.WrappedIterator.next(WrappedIterator.java:80)
at
com.hp.hpl.jena.util.iterator.Map1Iterator.next(Map1Iterator.java:47)
at
com.hp.hpl.jena.util.iterator.WrappedIterator.next(WrappedIterator.java:80)
at
com.hp.hpl.jena.rdf.model.impl.StmtIteratorImpl.next(StmtIteratorImpl.java:45)
at
com.hp.hpl.jena.rdf.model.impl.StmtIteratorImpl.next(StmtIteratorImpl.java:33)
at
com.ibm.team.jfs.rdf.internal.jena.tdb.JenaTxTdbProvider$7.run(JenaTxTdbProvider.java:950)
at
com.ibm.team.jfs.rdf.internal.jena.tdb.JenaTxTdbProvider$7.run(JenaTxTdbProvider.java:1)
at
com.ibm.team.jfs.rdf.internal.jena.tdb.JenaTxTdbProvider.storeOperation(JenaTxTdbProvider.java:208)
at
com.ibm.team.jfs.rdf.internal.jena.tdb.JenaTxTdbProvider.readAndSetCurrentIndexSize(JenaTxTdbProvider.java:941)
at
com.ibm.team.jfs.rdf.internal.jena.tdb.JenaTxTdbProvider.connect(JenaTxTdbProvider.java:488)
at
com.ibm.team.jfs.rdf.internal.jena.JenaRdfService.connect(JenaRdfService.java:284)
...
17:49:59,911 [678045802@qtp-316412636-5] DEBUG
com.hp.hpl.jena.tdb.transaction.TransactionManager - Txn[3]/R: finish
I am not sure what to make of it. I'll keep trying to produce a
reproducible test case which mimicks this behavior
Simon
Re: something that was written in a transaction is not found
Posted by Simon Helsen <sh...@ca.ibm.com>.
just tested with the latest from HEAD and the problem is still there. I
need to work more on a independent test case. With all the tracing that I
have on, I hope to actually recreate the situation. It is definitely
reproducible (it always happens in the 3rd read transaction after I
startup again, but I am thinking something goes wrong before the
kill/restart)
Simon
From:
Simon Helsen/Toronto/IBM@IBMCA
To:
dev@jena.apache.org
Cc:
Andy Seaborne <an...@gmail.com>, dev@jena.apache.org
Date:
08/22/2012 12:36 PM
Subject:
Re: something that was written in a transaction is not found
Andy,
I updated https://issues.apache.org/jira/browse/JENA-301. I think that one
can be closed.
FYI I had created a new snapshot with the status of HEAD about 2 hours ago
and with these changes (which fixed 301), the exception below remains.
Moreover, I checked if that problem was also bound to direct mode, but it
wasn't. Both mapped and direct mode showed the same exception.
However, I just noticed a whole whack of new deliveries which I have not
yet tested. I'll do that, but as for the time of writing, the exception
Quad: predicate cannot be null
is still a problem
Simon
From:
Andy Seaborne <an...@apache.org>
To:
dev@jena.apache.org
Date:
08/22/2012 04:31 AM
Subject:
Re: something that was written in a transaction is not found
On 21/08/12 23:32, Simon Helsen wrote:
> I am seeing for each write transaction "Txn[8]/W: Add to pending
> queue". I assume this is ok?
Yes. It will typically do this because of JENA-256. 9 in 10 write
transactions will do that in a serial work load.
> Then, when I kill the process and start again, I have the following
> sequence, leading to the Quad: predicate cannot be null
This may be JENA-301 which is an issue across restart.
> this is all on 2.7.4 from HEAD
When exactly?
Please try the current svn head or last night's build. Not marked
fixed, but a workaround to *an* issue is, as of yesterday, in svn trunk.
(also - run in mapped mode and see if it's different - that would be
useful information for JENA-301).
Andy
Re: something that was written in a transaction is not found
Posted by Simon Helsen <sh...@ca.ibm.com>.
Andy,
I updated https://issues.apache.org/jira/browse/JENA-301. I think that one
can be closed.
FYI I had created a new snapshot with the status of HEAD about 2 hours ago
and with these changes (which fixed 301), the exception below remains.
Moreover, I checked if that problem was also bound to direct mode, but it
wasn't. Both mapped and direct mode showed the same exception.
However, I just noticed a whole whack of new deliveries which I have not
yet tested. I'll do that, but as for the time of writing, the exception
Quad: predicate cannot be null
is still a problem
Simon
From:
Andy Seaborne <an...@apache.org>
To:
dev@jena.apache.org
Date:
08/22/2012 04:31 AM
Subject:
Re: something that was written in a transaction is not found
On 21/08/12 23:32, Simon Helsen wrote:
> I am seeing for each write transaction "Txn[8]/W: Add to pending
> queue". I assume this is ok?
Yes. It will typically do this because of JENA-256. 9 in 10 write
transactions will do that in a serial work load.
> Then, when I kill the process and start again, I have the following
> sequence, leading to the Quad: predicate cannot be null
This may be JENA-301 which is an issue across restart.
> this is all on 2.7.4 from HEAD
When exactly?
Please try the current svn head or last night's build. Not marked
fixed, but a workaround to *an* issue is, as of yesterday, in svn trunk.
(also - run in mapped mode and see if it's different - that would be
useful information for JENA-301).
Andy
Re: something that was written in a transaction is not found
Posted by Andy Seaborne <an...@apache.org>.
On 21/08/12 23:32, Simon Helsen wrote:
> I am seeing for each write transaction "Txn[8]/W: Add to pending
> queue". I assume this is ok?
Yes. It will typically do this because of JENA-256. 9 in 10 write
transactions will do that in a serial work load.
> Then, when I kill the process and start again, I have the following
> sequence, leading to the Quad: predicate cannot be null
This may be JENA-301 which is an issue across restart.
> this is all on 2.7.4 from HEAD
When exactly?
Please try the current svn head or last night's build. Not marked
fixed, but a workaround to *an* issue is, as of yesterday, in svn trunk.
(also - run in mapped mode and see if it's different - that would be
useful information for JENA-301).
Andy