Uploaded image for project: 'Blazegraph (by SYSTAP)'
  1. Blazegraph (by SYSTAP)
  2. BLZG-1268

NPE during read-only namespace resolution caused by RDR Truth Maintenance and GRS concurrent modification

    Details

    • Type: Bug
    • Status: In Progress
    • Priority: Medium
    • Resolution: Unresolved
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None

      Description

      While running the wikidata updater, I've got the following NPE error:

      ERROR: BigdataRDFServlet.java:191: cause=java.util.concurrent.ExecutionException: java.lang.NullPointerException, query=SPARQL-QUERY: queryStr=SELECT DISTINCT ?s
      WHERE

      Unknown macro: { <http}

      java.util.concurrent.ExecutionException: java.lang.NullPointerException
      at java.util.concurrent.FutureTask.report(FutureTask.java:122)
      at java.util.concurrent.FutureTask.get(FutureTask.java:188)
      at com.bigdata.rdf.sail.webapp.BigdataServlet.submitApiTask(BigdataServlet.java:261)
      at com.bigdata.rdf.sail.webapp.QueryServlet.doSparqlQuery(QueryServlet.java:532)
      at com.bigdata.rdf.sail.webapp.QueryServlet.doPost(QueryServlet.java:189)
      at com.bigdata.rdf.sail.webapp.RESTServlet.doPost(RESTServlet.java:237)
      at com.bigdata.rdf.sail.webapp.MultiTenancyServlet.doPost(MultiTenancyServlet.java:137)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
      at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808)
      at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587)
      at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
      at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)
      at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)
      at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)
      at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)
      at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
      at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)
      at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
      at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:215)
      at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:110)
      at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
      at org.eclipse.jetty.server.Server.handle(Server.java:497)
      at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310)
      at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
      at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)
      at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
      at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
      at java.lang.Thread.run(Thread.java:745)
      Caused by: java.lang.NullPointerException
      at com.bigdata.rdf.store.AbstractTripleStore.getValueFactory(AbstractTripleStore.java:438)
      at com.bigdata.rdf.sail.sparql.BigdataASTContext.<init>(BigdataASTContext.java:94)
      at com.bigdata.rdf.sail.sparql.Bigdata2ASTSPARQLParser.<init>(Bigdata2ASTSPARQLParser.java:99)
      at com.bigdata.rdf.sail.webapp.BigdataRDFContext.getQueryTask(BigdataRDFContext.java:2087)
      at com.bigdata.rdf.sail.webapp.QueryServlet$SparqlQueryTask.call(QueryServlet.java:604)
      at com.bigdata.rdf.sail.webapp.QueryServlet$SparqlQueryTask.call(QueryServlet.java:549)
      at com.bigdata.rdf.task.ApiTaskForIndexManager.call(ApiTaskForIndexManager.java:68)
      at java.util.concurrent.FutureTask.run(FutureTask.java:262)
      at com.bigdata.rdf.task.AbstractApiTask.submitApiTask(AbstractApiTask.java:365)
      at com.bigdata.rdf.sail.webapp.BigdataServlet.submitApiTask(BigdataServlet.java:258)
      ... 26 more
      ERROR: DefaultResourceLocator.java:531: java.lang.NullPointerException
      java.lang.NullPointerException
      at com.bigdata.btree.Node.getKeys(Node.java:269)
      at com.bigdata.btree.Node.findChild(Node.java:1182)
      at com.bigdata.btree.ChildIterator.<init>(ChildIterator.java:92)
      at com.bigdata.btree.Node.childIterator(Node.java:3384)
      at com.bigdata.btree.Node.postOrderIterator2(Node.java:3047)
      at com.bigdata.btree.Node.access$100(Node.java:86)
      at com.bigdata.btree.Node$2.expand(Node.java:3073)
      at cutthecrap.utils.striterators.Expanderator.getNext(Expanderator.java:59)
      at cutthecrap.utils.striterators.Prefetch.checkInit(Prefetch.java:27)
      at cutthecrap.utils.striterators.Prefetch.hasNext(Prefetch.java:35)
      at cutthecrap.utils.striterators.Striterator.hasNext(Striterator.java:89)
      at cutthecrap.utils.striterators.Appenderator.getNext(Appenderator.java:47)
      at cutthecrap.utils.striterators.Prefetch.checkInit(Prefetch.java:27)
      at cutthecrap.utils.striterators.Prefetch.hasNext(Prefetch.java:35)
      at cutthecrap.utils.striterators.Striterator.hasNext(Striterator.java:89)
      at cutthecrap.utils.striterators.Expanderator.getNext(Expanderator.java:41)
      at cutthecrap.utils.striterators.Expanderator.getNext(Expanderator.java:61)
      at cutthecrap.utils.striterators.Prefetch.checkInit(Prefetch.java:27)
      at cutthecrap.utils.striterators.Prefetch.hasNext(Prefetch.java:35)
      at cutthecrap.utils.striterators.Striterator.hasNext(Striterator.java:89)
      at cutthecrap.utils.striterators.Appenderator.getNext(Appenderator.java:47)
      at cutthecrap.utils.striterators.Prefetch.checkInit(Prefetch.java:27)
      at cutthecrap.utils.striterators.Prefetch.hasNext(Prefetch.java:35)
      at cutthecrap.utils.striterators.Striterator.hasNext(Striterator.java:89)
      at cutthecrap.utils.striterators.Expanderator.getNext(Expanderator.java:54)
      at cutthecrap.utils.striterators.Prefetch.checkInit(Prefetch.java:27)
      at cutthecrap.utils.striterators.Prefetch.hasNext(Prefetch.java:35)
      at cutthecrap.utils.striterators.Striterator.hasNext(Striterator.java:89)
      at com.bigdata.btree.AbstractNode$PostOrderEntryIterator.hasNext(AbstractNode.java:654)
      at com.bigdata.sparse.AbstractAtomicRowReadOrWrite.atomicRead(AbstractAtomicRowReadOrWrite.java:250)
      at com.bigdata.sparse.AbstractAtomicRowReadOrWrite.atomicRead(AbstractAtomicRowReadOrWrite.java:157)
      at com.bigdata.sparse.AtomicRowRead.apply(AtomicRowRead.java:98)
      at com.bigdata.sparse.AtomicRowRead.apply(AtomicRowRead.java:36)
      at com.bigdata.btree.AbstractBTree.submit(AbstractBTree.java:3184)
      at com.bigdata.sparse.SparseRowStore.read(SparseRowStore.java:531)
      at com.bigdata.sparse.SparseRowStore.read(SparseRowStore.java:414)
      at com.bigdata.relation.locator.DefaultResourceLocator.locateResourceOn(DefaultResourceLocator.java:778)
      at com.bigdata.relation.locator.DefaultResourceLocator.locateResource(DefaultResourceLocator.java:499)
      at com.bigdata.relation.locator.DefaultResourceLocator.cacheMiss(DefaultResourceLocator.java:383)
      at com.bigdata.relation.locator.DefaultResourceLocator.locate(DefaultResourceLocator.java:335)
      at com.bigdata.rdf.sail.BigdataSail$BigdataSailReadOnlyConnection.newTx(BigdataSail.java:4623)
      at com.bigdata.rdf.sail.BigdataSail$BigdataSailReadOnlyConnection.<init>(BigdataSail.java:4504)
      at com.bigdata.rdf.sail.BigdataSail._getReadOnlyConnection(BigdataSail.java:1587)
      at com.bigdata.rdf.sail.BigdataSail.getReadOnlyConnection(BigdataSail.java:1561)
      at com.bigdata.rdf.sail.BigdataSailRepository.getReadOnlyConnection(BigdataSailRepository.java:110)
      at com.bigdata.rdf.task.AbstractApiTask.getQueryConnection(AbstractApiTask.java:253)
      at com.bigdata.rdf.task.AbstractApiTask.getQueryConnection(AbstractApiTask.java:216)
      at com.bigdata.rdf.sail.webapp.QueryServlet$SparqlQueryTask.call(QueryServlet.java:582)
      at com.bigdata.rdf.sail.webapp.QueryServlet$SparqlQueryTask.call(QueryServlet.java:549)
      at com.bigdata.rdf.task.ApiTaskForIndexManager.call(ApiTaskForIndexManager.java:68)
      at java.util.concurrent.FutureTask.run(FutureTask.java:262)
      at com.bigdata.rdf.task.AbstractApiTask.submitApiTask(AbstractApiTask.java:365)
      at com.bigdata.rdf.sail.webapp.BigdataServlet.submitApiTask(BigdataServlet.java:258)
      at com.bigdata.rdf.sail.webapp.QueryServlet.doSparqlQuery(QueryServlet.java:532)
      at com.bigdata.rdf.sail.webapp.QueryServlet.doPost(QueryServlet.java:189)
      at com.bigdata.rdf.sail.webapp.RESTServlet.doPost(RESTServlet.java:237)
      at com.bigdata.rdf.sail.webapp.MultiTenancyServlet.doPost(MultiTenancyServlet.java:137)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
      at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808)
      at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587)
      at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
      at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)
      at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)
      at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)
      at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)
      at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
      at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)
      at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
      at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:215)
      at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:110)
      at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
      at org.eclipse.jetty.server.Server.handle(Server.java:497)
      at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310)
      at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
      at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)
      at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
      at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
      at java.lang.Thread.run(Thread.java:745)

      This seems not happen a number of times, though I can not reliably reproduce it in isolated conditions. This happens on 1.5.1 with wikidata patch (that backports http://trac.bigdata.com/ticket/1179).

      1. log
        39 kB
        stasmalyshev

        Issue Links

          Activity

          Hide
          stasmalyshev stasmalyshev added a comment -

          Full log, in case it's useful. Ignore the syntax errors, they are unrelated.

          Show
          stasmalyshev stasmalyshev added a comment - Full log, in case it's useful. Ignore the syntax errors, they are unrelated.
          Hide
          bryanthompson bryanthompson added a comment -

          Those syntax errors might not be unrelated. They will cause the query task to fail. Depending on what is going on (probably in your code) that might cause the update task to be cancelled (assuming the query is in service of the update). So that might explain how the update gets cancelled and why we are seeing what I am presuming is a data race during the tear down of a read-only index view.

          Show
          bryanthompson bryanthompson added a comment - Those syntax errors might not be unrelated. They will cause the query task to fail. Depending on what is going on (probably in your code) that might cause the update task to be cancelled (assuming the query is in service of the update). So that might explain how the update gets cancelled and why we are seeing what I am presuming is a data race during the tear down of a read-only index view.
          Hide
          stasmalyshev stasmalyshev added a comment -

          Well, maybe but doubtful for me since NPEs seem to happen in different time than syntax errors (any way to get timestamps into Blazegraph logs?) But I can experiment with it more.

          Show
          stasmalyshev stasmalyshev added a comment - Well, maybe but doubtful for me since NPEs seem to happen in different time than syntax errors (any way to get timestamps into Blazegraph logs?) But I can experiment with it more.
          Hide
          stasmalyshev stasmalyshev added a comment -

          Another one:

          ERROR: DefaultResourceLocator.java:531: java.lang.RuntimeException: leaf=com.bigdata.btree.Leaf@5a783658#110456047928421(deleted)

          { isDirty=false, isDeleted=true, addr=110456047928421, parent=N/A, isRoot=false, data=NA}::namespace=wdq.spo, timestamp=readOnly(1431734306181), readTime=readOnly(1431734306181)
          java.lang.RuntimeException: leaf=com.bigdata.btree.Leaf@5a783658#110456047928421(deleted){ isDirty=false, isDeleted=true, addr=110456047928421, parent=N/A, isRoot=false, data=NA}

          ::namespace=wdq.spo, timestamp=readOnly(1431734306181), readTime=readOnly(1431734306181)
          at com.bigdata.relation.locator.DefaultResourceLocator.locateResourceOn(DefaultResourceLocator.java:784)
          at com.bigdata.relation.locator.DefaultResourceLocator.locateResource(DefaultResourceLocator.java:499)
          at com.bigdata.relation.locator.DefaultResourceLocator.cacheMiss(DefaultResourceLocator.java:383)
          at com.bigdata.relation.locator.DefaultResourceLocator.locate(DefaultResourceLocator.java:335)
          at com.bigdata.rdf.store.AbstractTripleStore.getSPORelation(AbstractTripleStore.java:2002)
          at com.bigdata.rdf.store.AbstractTripleStore.getAccessPath(AbstractTripleStore.java:3138)
          at com.bigdata.rdf.sparql.ast.optimizers.ASTRangeCountOptimizer.estimateCardinalities(ASTRangeCountOptimizer.java:199)
          at com.bigdata.rdf.sparql.ast.optimizers.ASTRangeCountOptimizer.estimateCardinality(ASTRangeCountOptimizer.java:191)
          at com.bigdata.rdf.sparql.ast.optimizers.ASTRangeCountOptimizer$RangeCountTask.call(ASTRangeCountOptimizer.java:171)
          at com.bigdata.rdf.sparql.ast.optimizers.ASTRangeCountOptimizer$RangeCountTask.call(ASTRangeCountOptimizer.java:154)
          at java.util.concurrent.FutureTask.run(FutureTask.java:262)
          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
          at java.lang.Thread.run(Thread.java:745)
          Caused by: java.lang.NullPointerException: leaf=com.bigdata.btree.Leaf@5a783658#110456047928421(deleted)

          { isDirty=false, isDeleted=true, addr=110456047928421, parent=N/A, isRoot=false, data=NA}

          at com.bigdata.btree.Leaf.getKeys(Leaf.java:180)
          at com.bigdata.btree.AbstractNode$PostOrderEntryIterator$1.expand(AbstractNode.java:699)
          at cutthecrap.utils.striterators.Expanderator.getNext(Expanderator.java:59)
          at cutthecrap.utils.striterators.Prefetch.checkInit(Prefetch.java:27)
          at cutthecrap.utils.striterators.Prefetch.hasNext(Prefetch.java:35)
          at cutthecrap.utils.striterators.Striterator.hasNext(Striterator.java:89)
          at com.bigdata.btree.AbstractNode$PostOrderEntryIterator.hasNext(AbstractNode.java:654)
          at com.bigdata.sparse.AbstractAtomicRowReadOrWrite.atomicRead(AbstractAtomicRowReadOrWrite.java:250)
          at com.bigdata.sparse.AbstractAtomicRowReadOrWrite.atomicRead(AbstractAtomicRowReadOrWrite.java:157)
          at com.bigdata.sparse.AtomicRowRead.apply(AtomicRowRead.java:98)
          at com.bigdata.sparse.AtomicRowRead.apply(AtomicRowRead.java:36)
          at com.bigdata.btree.AbstractBTree.submit(AbstractBTree.java:3184)
          at com.bigdata.sparse.SparseRowStore.read(SparseRowStore.java:531)
          at com.bigdata.sparse.SparseRowStore.read(SparseRowStore.java:414)
          at com.bigdata.relation.locator.DefaultResourceLocator.locateResourceOn(DefaultResourceLocator.java:779)
          ... 13 more

          Didn't do any queries for hours before that, so pretty sure it's not syntax errors.

          Show
          stasmalyshev stasmalyshev added a comment - Another one: ERROR: DefaultResourceLocator.java:531: java.lang.RuntimeException: leaf=com.bigdata.btree.Leaf@5a783658#110456047928421(deleted) { isDirty=false, isDeleted=true, addr=110456047928421, parent=N/A, isRoot=false, data=NA}::namespace=wdq.spo, timestamp=readOnly(1431734306181), readTime=readOnly(1431734306181) java.lang.RuntimeException: leaf=com.bigdata.btree.Leaf@5a783658#110456047928421(deleted){ isDirty=false, isDeleted=true, addr=110456047928421, parent=N/A, isRoot=false, data=NA} ::namespace=wdq.spo, timestamp=readOnly(1431734306181), readTime=readOnly(1431734306181) at com.bigdata.relation.locator.DefaultResourceLocator.locateResourceOn(DefaultResourceLocator.java:784) at com.bigdata.relation.locator.DefaultResourceLocator.locateResource(DefaultResourceLocator.java:499) at com.bigdata.relation.locator.DefaultResourceLocator.cacheMiss(DefaultResourceLocator.java:383) at com.bigdata.relation.locator.DefaultResourceLocator.locate(DefaultResourceLocator.java:335) at com.bigdata.rdf.store.AbstractTripleStore.getSPORelation(AbstractTripleStore.java:2002) at com.bigdata.rdf.store.AbstractTripleStore.getAccessPath(AbstractTripleStore.java:3138) at com.bigdata.rdf.sparql.ast.optimizers.ASTRangeCountOptimizer.estimateCardinalities(ASTRangeCountOptimizer.java:199) at com.bigdata.rdf.sparql.ast.optimizers.ASTRangeCountOptimizer.estimateCardinality(ASTRangeCountOptimizer.java:191) at com.bigdata.rdf.sparql.ast.optimizers.ASTRangeCountOptimizer$RangeCountTask.call(ASTRangeCountOptimizer.java:171) at com.bigdata.rdf.sparql.ast.optimizers.ASTRangeCountOptimizer$RangeCountTask.call(ASTRangeCountOptimizer.java:154) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745) Caused by: java.lang.NullPointerException: leaf=com.bigdata.btree.Leaf@5a783658#110456047928421(deleted) { isDirty=false, isDeleted=true, addr=110456047928421, parent=N/A, isRoot=false, data=NA} at com.bigdata.btree.Leaf.getKeys(Leaf.java:180) at com.bigdata.btree.AbstractNode$PostOrderEntryIterator$1.expand(AbstractNode.java:699) at cutthecrap.utils.striterators.Expanderator.getNext(Expanderator.java:59) at cutthecrap.utils.striterators.Prefetch.checkInit(Prefetch.java:27) at cutthecrap.utils.striterators.Prefetch.hasNext(Prefetch.java:35) at cutthecrap.utils.striterators.Striterator.hasNext(Striterator.java:89) at com.bigdata.btree.AbstractNode$PostOrderEntryIterator.hasNext(AbstractNode.java:654) at com.bigdata.sparse.AbstractAtomicRowReadOrWrite.atomicRead(AbstractAtomicRowReadOrWrite.java:250) at com.bigdata.sparse.AbstractAtomicRowReadOrWrite.atomicRead(AbstractAtomicRowReadOrWrite.java:157) at com.bigdata.sparse.AtomicRowRead.apply(AtomicRowRead.java:98) at com.bigdata.sparse.AtomicRowRead.apply(AtomicRowRead.java:36) at com.bigdata.btree.AbstractBTree.submit(AbstractBTree.java:3184) at com.bigdata.sparse.SparseRowStore.read(SparseRowStore.java:531) at com.bigdata.sparse.SparseRowStore.read(SparseRowStore.java:414) at com.bigdata.relation.locator.DefaultResourceLocator.locateResourceOn(DefaultResourceLocator.java:779) ... 13 more Didn't do any queries for hours before that, so pretty sure it's not syntax errors.
          Hide
          bryanthompson bryanthompson added a comment -

          Root cause: Truth maintenance in the RDR mode when retracting statements. See BLZG-1285.

          Workaround: Disable RDR.

          Note: The following are not yet clear but will be addressed by BLZG-1285

          • Why was the truth maintenance logic for RDR taking so much time and disk (temporary stores) when the data was not actually using statements about statements?
          • Why was the truth maintenance logic causing writes on the global row store when registering a focus store on a temporary store in support of truth maintenance? Note that this implies that truth maintenance itself may have problems with group commit (not just for RDR enabled stores).
          • Why were those writes on the global row store resulting in a concurrent modification problem with the global row store view used by the DefaultResourceLocator to resolve a current view of the main triple store (which was the root cause for this ticket).
          Show
          bryanthompson bryanthompson added a comment - Root cause: Truth maintenance in the RDR mode when retracting statements. See BLZG-1285 . Workaround: Disable RDR. Note: The following are not yet clear but will be addressed by BLZG-1285 Why was the truth maintenance logic for RDR taking so much time and disk (temporary stores) when the data was not actually using statements about statements? Why was the truth maintenance logic causing writes on the global row store when registering a focus store on a temporary store in support of truth maintenance? Note that this implies that truth maintenance itself may have problems with group commit (not just for RDR enabled stores). Why were those writes on the global row store resulting in a concurrent modification problem with the global row store view used by the DefaultResourceLocator to resolve a current view of the main triple store (which was the root cause for this ticket).

            People

            • Assignee:
              bryanthompson bryanthompson
              Reporter:
              stasmalyshev stasmalyshev
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated: