7 Replies Latest reply on Jun 30, 2012 6:10 PM by jonathandfields

NPE in SQL2 search, Rest Server

jonathandfields Jun 29, 2012 7:11 PM

Modeshape 3.0 Alpha6, JBoss AS 7.1 kit, Infinispan BDBJE cache store

First, great work on Alpha6. I dropped the kit into a clean AS 7.1, added BDBJE, and my batch load test is working (Asynch EJB using BMT), and is currently loading well over a million nodes of real test data....

A batch load was running in an asynchronous EJB, loading test data (using BMT transactions to batch the updates).
JCR-SQL2 query sent to the Rest server: select * from [nt:unstructured] as n where n.[Last Name] = "Smith" (and there are "Smith" nodes in the repo). All nodes are nt:unstructured.
NPE exception shown below. If you'd like this in JIRA please let me know.
Sorry, I cannot provide the actual data and search, but it is confidential client data.

Thanks,

Jon

17:02:19,826 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host].[/modeshape-rest].[Resteasy]] (http-localhost-127.0.0.1-8080-1) Servlet.service() for servlet Resteasy threw exception: org.jboss.resteasy.spi.UnhandledException: java.lang.NullPointerException

at org.jboss.resteasy.core.SynchronousDispatcher.handleApplicationException(SynchronousDispatcher.java:340) [resteasy-jaxrs-2.3.2.Final.jar:]

at org.jboss.resteasy.core.SynchronousDispatcher.handleException(SynchronousDispatcher.java:214) [resteasy-jaxrs-2.3.2.Final.jar:]

at org.jboss.resteasy.core.SynchronousDispatcher.handleInvokerException(SynchronousDispatcher.java:190) [resteasy-jaxrs-2.3.2.Final.jar:]

at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:540) [resteasy-jaxrs-2.3.2.Final.jar:]

at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:502) [resteasy-jaxrs-2.3.2.Final.jar:]

at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119) [resteasy-jaxrs-2.3.2.Final.jar:]

at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208) [resteasy-jaxrs-2.3.2.Final.jar:]

at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55) [resteasy-jaxrs-2.3.2.Final.jar:]

at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50) [resteasy-jaxrs-2.3.2.Final.jar:]

at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.0.Final.jar:1.0.0.Final]

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.13.Final.jar:]

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.13.Final.jar:]

at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.13.Final.jar:]

at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.13.Final.jar:]

at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:489) [jbossweb-7.0.13.Final.jar:]

at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153) [jboss-as-web-7.1.1.Final.jar:7.1.1.Final]

at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.13.Final.jar:]

at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.13.Final.jar:]

at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.13.Final.jar:]

at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.13.Final.jar:]

at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.13.Final.jar:]

at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:671) [jbossweb-7.0.13.Final.jar:]

at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:930) [jbossweb-7.0.13.Final.jar:]

at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_27]

Caused by: java.lang.NullPointerException

at org.modeshape.jcr.cache.document.LazyCachedNode.getSegment(LazyCachedNode.java:172) [modeshape-jcr-3.0.0.Alpha6.jar:3.0.0.Alpha6]

at org.modeshape.jcr.cache.document.LazyCachedNode.getPath(LazyCachedNode.java:181) [modeshape-jcr-3.0.0.Alpha6.jar:3.0.0.Alpha6]

at org.modeshape.jcr.cache.PathCache.getPath(PathCache.java:45) [modeshape-jcr-3.0.0.Alpha6.jar:3.0.0.Alpha6]

at org.modeshape.jcr.query.lucene.basic.BasicTupleCollector.doCollect(BasicTupleCollector.java:187) [modeshape-jcr-3.0.0.Alpha6.jar:3.0.0.Alpha6]

at org.modeshape.jcr.query.lucene.LuceneQueryEngine$TupleCollector.collect(LuceneQueryEngine.java:378) [modeshape-jcr-3.0.0.Alpha6.jar:3.0.0.Alpha6]

at org.apache.lucene.search.BooleanScorer2.score(BooleanScorer2.java:281)

at org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:581)

at org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:383)

at org.modeshape.jcr.query.lucene.LuceneQueryEngine$LuceneAccessQuery.execute(LuceneQueryEngine.java:314) [modeshape-jcr-3.0.0.Alpha6.jar:3.0.0.Alpha6]

at org.modeshape.jcr.query.process.QueryProcessor.execute(QueryProcessor.java:96) [modeshape-jcr-3.0.0.Alpha6.jar:3.0.0.Alpha6]

at org.modeshape.jcr.query.process.QueryEngine.execute(QueryEngine.java:140) [modeshape-jcr-3.0.0.Alpha6.jar:3.0.0.Alpha6]

at org.modeshape.jcr.query.lucene.LuceneQueryEngine$1.getResults(LuceneQueryEngine.java:149) [modeshape-jcr-3.0.0.Alpha6.jar:3.0.0.Alpha6]

at org.modeshape.jcr.query.JcrQuery.execute(JcrQuery.java:119) [modeshape-jcr-3.0.0.Alpha6.jar:3.0.0.Alpha6]

at org.modeshape.web.jcr.rest.QueryHandler.postItem(QueryHandler.java:78) [modeshape-web-jcr-rest-3.0.0.Alpha6.jar:3.0.0.Alpha6]

at org.modeshape.web.jcr.rest.JcrResources.postJcrSql2Query(JcrResources.java:441) [modeshape-web-jcr-rest-3.0.0.Alpha6.jar:3.0.0.Alpha6]

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.6.0_27]

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [rt.jar:1.6.0_27]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [rt.jar:1.6.0_27]

at java.lang.reflect.Method.invoke(Method.java:597) [rt.jar:1.6.0_27]

at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:155) [resteasy-jaxrs-2.3.2.Final.jar:]

at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:257) [resteasy-jaxrs-2.3.2.Final.jar:]

at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:222) [resteasy-jaxrs-2.3.2.Final.jar:]

at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:211) [resteasy-jaxrs-2.3.2.Final.jar:]

at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:525) [resteasy-jaxrs-2.3.2.Final.jar:]

... 20 more

1. Re: NPE in SQL2 search, Rest Server

jonathandfields Jun 29, 2012 7:19 PM (in response to jonathandfields)

Also, note that after several minutes, and the data loader had loaded more data, the same query did not crash, and returned the correct results.
Actions
2. Re: NPE in SQL2 search, Rest Server

jonathandfields Jun 29, 2012 7:33 PM (in response to jonathandfields)

Observation: The exception occurs when loader EJB is either saving the Session or committing the UserTransaction (BMT). This takes about two minutes, as there are hundreds of nodes being saved.

When the loader is just creating nodes in the session, before the save/commit, the exception does not occur.
Actions
3. Re: NPE in SQL2 search, Rest Server

rhauch Jun 30, 2012 5:23 PM (in response to jonathandfields)

Thanks for reporting this, Jonathan. Please log this as a bug in JIRA.

IIUC, this sounds like you're querying while the EJB loader is performing the save or commit, which means something from the save is leaking into the session used for queries.

BTW, what takes two minutes ... just the Session.save()??
Actions
4. Re: NPE in SQL2 search, Rest Server

jonathandfields Jun 30, 2012 5:42 PM (in response to rhauch)

Will do on the JIRA.

The time is the combination of Session.save() and UserTransaction.commit() (I haven't measured them separately).

The save/commit are persisting around 10000 nodes with around 60000 properties, hence the time.

I've since cut the number of nodes in half, because I was seeing some transaction timeouts from Arjuna.

I'm beginning to test Modeshape against real data for evaluation purposes.
Actions
5. Re: NPE in SQL2 search, Rest Server

jonathandfields Jun 30, 2012 5:44 PM (in response to jonathandfields)

Each node does not have 60000 properties, that is the total number of properties created (calls to Node.setProperty()) before the save.
Actions
6. Re: NPE in SQL2 search, Rest Server

jonathandfields Jun 30, 2012 5:54 PM (in response to jonathandfields)

Essentially my test is loading around 50K nodes, each of which has about 100 descendent nodes, each with a several string properties. The total nodes will be around 5M when it is all loaded. That is typical of a real data set for me so I want to evaluate that with a distributed infinispan cache backed by BDBJE. (I haven't figured out how to setup the distributed cache yet, probably be asking for some help on that next week some time, once I get the servers set up :-)
Actions
7. Re: NPE in SQL2 search, Rest Server

jonathandfields Jun 30, 2012 6:10 PM (in response to jonathandfields)

MODE-1546 has been created.
Actions

Go to original post