Hi, I've been having some transactional issues with TDB in recent snapshots of Fuseki. Previous releases and snapshots worked fine, so I think it's an issue that has been introduced recently.
I have been running Fuseki with a reasonably standard configuration. My config file is just: @prefix tdb: <http://jena.hpl.hp.com/2008/tdb#> . @prefix rdf: <http://www.w3.org/1999/02/22-rdf-syntax-ns#> . @prefix rdfs: <http://www.w3.org/2000/01/rdf-schema#> . @prefix ja: <http://jena.hpl.hp.com/2005/11/Assembler#> . @prefix tdb: <http://jena.hpl.hp.com/2008/tdb#> . [] ja:loadClass "com.hp.hpl.jena.tdb.TDB" . tdb:DatasetTDB rdfs:subClassOf ja:RDFDataset . tdb:GraphTDB rdfs:subClassOf ja:Model . <#dataset> rdf:type tdb:DatasetTDB ; tdb:location "DB" ; And the command line I use to start Fuseki is: fuseki-server --update --desc tdb.ttl /dataset We have a process that throws a number of queries and updates at the server, all in parallel (multiple threads, operating independently). For my particular problem, an example query is: SELECT (COUNT(*) AS ?count) WHERE {GRAPH <data:output> {?a1 <http://example.com/ex#spouseOf> ?a2}} An example update is: INSERT {GRAPH <data:output> {?z <http://example.com/ex#parentOf> ?y}} WHERE {{{GRAPH <data:output> {?z <http://example.com/ex#parentOf> ?x}} UNION {GRAPH <data:input> {?z <http://example.com/ex#parentOf> ?x}}} . GRAPH <data:input> {?x <http://example.com/ex#siblingOf> ?y}} (this is in a test suite, which is the reason for the unusual graph URIs. Those URIs do not appear to be a problem) Up until a snapshot I had in December, the process would run cleanly through to completion. However, the recent snapshots of Fuseki have started to fail due to transactional issues. Because the client code is multithreaded, the exact log differs during each run, but here are some examples... The following is a relevant snapshot of the log (discussion below): 15:10:43 INFO Fuseki :: [64] POST http://localhost:3030/dataset/update 15:10:43 INFO Fuseki :: [63] POST http://localhost:3030/dataset/update 15:10:43 INFO Fuseki :: [64] 204 No Content 15:10:43 INFO Fuseki :: [65] GET http://localhost:3030/dataset/query?query=SELECT+%28COUNT%28*%29+AS+%3Fcount%29+WHERE+%7BGRAPH+%3Cdata%3Aoutput%3E+%7B%3F%CB%901+%3Chttp%3A%2F%2Fexample.com%2Fex%23siblingOf%3E+%3F%CB%902%7D%7D 15:10:43 INFO Fuseki :: [66] GET http://localhost:3030/dataset/query?query=SELECT+%28COUNT%28*%29+AS+%3Fcount%29+WHERE+%7BGRAPH+%3Cdata%3Aoutput%3E+%7B%3F%CB%901+%3Chttp%3A%2F%2Fexample.com%2Fex%23spouseOf%3E+%3F%CB%902%7D%7D 15:10:43 INFO Fuseki :: [66] Query = SELECT (COUNT(*) AS ?count) WHERE {GRAPH <data:output> {??1 <http://example.com/ex#spouseOf> ??2}} 15:10:43 INFO Fuseki :: [65] Query = SELECT (COUNT(*) AS ?count) WHERE {GRAPH <data:output> {??1 <http://example.com/ex#siblingOf> ??2}} 15:10:43 INFO Fuseki :: [66] OK/select 15:10:43 INFO Fuseki :: [65] OK/select 15:10:43 WARN Fuseki :: [63] RC = 500 : leaveCriticalSection: No lock held (qtp519936919-17) Thread R/W: 0/0 :: Model R/W: 2/0 (thread: qtp519936919-17) com.hp.hpl.jena.shared.JenaException: leaveCriticalSection: No lock held (qtp519936919-17) Thread R/W: 0/0 :: Model R/W: 2/0 (thread: qtp519936919-17) at com.hp.hpl.jena.shared.LockMRSW.leaveCriticalSection(LockMRSW.java:175) at com.hp.hpl.jena.tdb.transaction.TransactionManager$TSM_WriteBackEndTxn.readerFinishes(TransactionManager.java:198) at com.hp.hpl.jena.tdb.transaction.TransactionManager.readerFinishes(TransactionManager.java:677) at com.hp.hpl.jena.tdb.transaction.TransactionManager.noteTxnCommit(TransactionManager.java:531) at com.hp.hpl.jena.tdb.transaction.TransactionManager.notifyCommit(TransactionManager.java:382) at com.hp.hpl.jena.tdb.transaction.Transaction.commit(Transaction.java:122) at com.hp.hpl.jena.tdb.transaction.Transaction.close(Transaction.java:179) at com.hp.hpl.jena.tdb.transaction.DatasetGraphTxn.end(DatasetGraphTxn.java:55) at com.hp.hpl.jena.tdb.transaction.DatasetGraphTransaction._end(DatasetGraphTransaction.java:118) at com.hp.hpl.jena.tdb.migrate.DatasetGraphTrackActive.end(DatasetGraphTrackActive.java:76) at org.apache.jena.fuseki.servlets.HttpAction.endWrite(HttpAction.java:119) at org.apache.jena.fuseki.servlets.SPARQL_Update.execute(SPARQL_Update.java:238) at org.apache.jena.fuseki.servlets.SPARQL_Update.executeBody(SPARQL_Update.java:205) at org.apache.jena.fuseki.servlets.SPARQL_Update.perform(SPARQL_Update.java:117) at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.doCommon(SPARQL_ServletBase.java:92) at org.apache.jena.fuseki.servlets.SPARQL_Update.doPost(SPARQL_Update.java:78) at javax.servlet.http.HttpServlet.service(HttpServlet.java:727) at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:547) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:480) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:225) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:941) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:409) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:186) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:875) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:110) at org.eclipse.jetty.server.Server.handle(Server.java:349) at org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:441) at org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:919) at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:588) at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:218) at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:50) at org.eclipse.jetty.server.nio.BlockingChannelConnector$BlockingChannelEndPoint.run(BlockingChannelConnector.java:293) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598) at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533) at java.lang.Thread.run(Thread.java:680) 15:10:43 INFO Fuseki :: [66] 200 OK 15:10:43 INFO Fuseki :: [63] 500 leaveCriticalSection: No lock held (qtp519936919-17) Thread R/W: 0/0 :: Model R/W: 2/0 (thread: qtp519936919-17) 15:10:43 INFO Fuseki :: [65] 200 OK You can see two updates being sent ([64/63] They are slightly different operations), followed shortly by two queries on the same data that was being updated [65/66]. While processing the first update [63] the locking exception was encountered. It appears that the server expected a lock to be held but found that this was not true. As this was non-fatal, processing continued. The queries returned successfully. Shortly after this, a similar sequence of operations was executed, and the lock problem showed up a little differently: 15:10:43 INFO Fuseki :: [69] POST http://localhost:3030/dataset/update 15:10:43 INFO Fuseki :: [70] POST http://localhost:3030/dataset/update 15:10:43 INFO Fuseki :: [71] GET http://localhost:3030/dataset/query?query=SELECT+%28COUNT%28*%29+AS+%3Fcount%29+WHERE+%7BGRAPH+%3Cdata%3Aoutput%3E+%7B%3F%CB%901+%3Chttp%3A%2F%2Fexample.com%2Fex%23spouseOf%3E+%3F%CB%902%7D%7D 15:10:43 INFO Fuseki :: [71] Query = SELECT (COUNT(*) AS ?count) WHERE {GRAPH <data:output> {??1 <http://example.com/ex#spouseOf> ??2}} 15:10:43 INFO Fuseki :: [72] GET http://localhost:3030/dataset/query?query=SELECT+%28COUNT%28*%29+AS+%3Fcount%29+WHERE+%7BGRAPH+%3Cdata%3Aoutput%3E+%7B%3F%CB%901+%3Chttp%3A%2F%2Fexample.com%2Fex%23siblingOf%3E+%3F%CB%902%7D%7D 15:10:43 INFO Fuseki :: [72] Query = SELECT (COUNT(*) AS ?count) WHERE {GRAPH <data:output> {??1 <http://example.com/ex#siblingOf> ??2}} 15:10:43 INFO Fuseki :: [71] OK/select 15:10:43 WARN SPARQL_Update$HttpActionUpdate :: Transaction still active in endWriter - no commit or abort seen (forced abort) 15:10:43 WARN Fuseki :: [69] RC = 500 : Read-only block manager com.hp.hpl.jena.tdb.TDBException: Read-only block manager at com.hp.hpl.jena.tdb.base.block.BlockMgrReadonly.beginUpdate(BlockMgrReadonly.java:33) at com.hp.hpl.jena.tdb.base.page.PageBlockMgr.startUpdate(PageBlockMgr.java:132) at com.hp.hpl.jena.tdb.index.bplustree.BPlusTree.startUpdateBlkMgr(BPlusTree.java:401) at com.hp.hpl.jena.tdb.index.bplustree.BPlusTree.addAndReturnOld(BPlusTree.java:321) at com.hp.hpl.jena.tdb.index.bplustree.BPlusTree.add(BPlusTree.java:315) at com.hp.hpl.jena.tdb.index.TupleIndexRecord.performAdd(TupleIndexRecord.java:60) at com.hp.hpl.jena.tdb.index.TupleIndexBase.add(TupleIndexBase.java:61) at com.hp.hpl.jena.tdb.index.TupleTable.add(TupleTable.java:71) at com.hp.hpl.jena.tdb.nodetable.NodeTupleTableConcrete.addRow(NodeTupleTableConcrete.java:87) at com.hp.hpl.jena.tdb.store.QuadTable.add(QuadTable.java:66) at com.hp.hpl.jena.tdb.store.DatasetGraphTDB.addToNamedGraph(DatasetGraphTDB.java:144) at com.hp.hpl.jena.sparql.core.DatasetGraphTriplesQuads.add(DatasetGraphTriplesQuads.java:47) at com.hp.hpl.jena.sparql.core.DatasetGraphTriplesQuads.add(DatasetGraphTriplesQuads.java:32) at com.hp.hpl.jena.tdb.migrate.DatasetGraphTrackActive.add(DatasetGraphTrackActive.java:135) at com.hp.hpl.jena.sparql.core.DatasetGraphWrapper.add(DatasetGraphWrapper.java:72) at com.hp.hpl.jena.sparql.modify.UpdateEngineWorker.execInsert(UpdateEngineWorker.java:470) at com.hp.hpl.jena.sparql.modify.UpdateEngineWorker.visit(UpdateEngineWorker.java:347) at com.hp.hpl.jena.sparql.modify.request.UpdateModify.visit(UpdateModify.java:97) at com.hp.hpl.jena.sparql.modify.UpdateEngineMain.execute(UpdateEngineMain.java:40) at com.hp.hpl.jena.sparql.modify.UpdateProcessorBase.execute(UpdateProcessorBase.java:60) at com.hp.hpl.jena.update.UpdateAction.execute$(UpdateAction.java:330) at com.hp.hpl.jena.update.UpdateAction.execute(UpdateAction.java:323) at com.hp.hpl.jena.update.UpdateAction.execute(UpdateAction.java:303) at com.hp.hpl.jena.update.UpdateAction.execute(UpdateAction.java:255) at org.apache.jena.fuseki.servlets.SPARQL_Update.execute(SPARQL_Update.java:234) at org.apache.jena.fuseki.servlets.SPARQL_Update.executeBody(SPARQL_Update.java:205) at org.apache.jena.fuseki.servlets.SPARQL_Update.perform(SPARQL_Update.java:117) at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.doCommon(SPARQL_ServletBase.java:92) at org.apache.jena.fuseki.servlets.SPARQL_Update.doPost(SPARQL_Update.java:78) at javax.servlet.http.HttpServlet.service(HttpServlet.java:727) at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:547) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:480) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:225) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:941) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:409) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:186) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:875) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:110) at org.eclipse.jetty.server.Server.handle(Server.java:349) at org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:441) at org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:919) at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:588) at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:218) at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:50) at org.eclipse.jetty.server.nio.BlockingChannelConnector$BlockingChannelEndPoint.run(BlockingChannelConnector.java:293) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598) at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533) at java.lang.Thread.run(Thread.java:680) 15:10:43 INFO Fuseki :: [71] 200 OK 15:10:43 INFO Fuseki :: [72] OK/select 15:10:43 INFO Fuseki :: [69] 500 Read-only block manager This time, the update in [69] seemed to find a lock still active (perhaps the one that update [63] was unable to find?) and logged the exception. Again, because the exception was non-fatal, the system continued. Four queries later, the server deadlocked during a SELECT/COUNT. Another run made it further through (only logging the first exception). At the end of the test the data had not been updated as expected, and when the test attempted to clean up the graphs with a DELETE operation the server again deadlocked. I have found this behavior is consistent with the three snapshots in: https://repository.apache.org/content/repositories/snapshots/org/apache/jena/jena-fuseki/0.2.1-incubating-SNAPSHOT/ Snapshots taken up to May of 2011 all worked correctly (I apologise for not having a smaller time window - I was working on another project during that period). I found Fuseki-0.1.0 (release), Fuseki-0.2.0 (release) and Fuseki-0.2.1-SNAPSHOT (May 10, 2011) all work without issue. All our tests and deployments on these systems work consistently and correctly. I would like to try some of the more recent snapshots, but the Apache repository only takes me back through this month, and I am unable to find earlier binaries. Please let me know if there is any further information I can provide. Regards, Paul Gearon
