1 Reply Latest reply on Sep 9, 2016 1:20 AM by Horia Chiorean

    Inconsistent reads produced by concurrent write and read operations during heavy load in Modeshape 5.1.0.Final

    Kornelius Prell Newbie

      Hello Modeshape community,

       

      we're currently experiencing some weird behaviour on read-operations in a load test scenario with Modeshape 5.1.0.Final and Wildfly 10.

      This error first surfaced in HP LoadRunner load tests, running for our custom application concurrently with 12 simulated clients.

       

      The following project is an attempt to reproduce this issue with jmeter:

      https://github.com/ditemis/modeshape-concurrent-write-read-load-test

       

      The tests perform the following actions:

      • RESTful request to create a node with some subnodes and read it again immediately after session.save().
      • RESTful request to update some attributes on the created node and its subnodes.

       

      These actions are executed from a jmeter test concurrently for multiple users.

      In a tiny amount of transactions (~ 0.01%) the read operation (immediately after the node creation) isn't able to properly return the created node.

      The following exception occurs:

      2016-09-08 15:26:06,141 ERROR [io.undertow.request] (default task-39) UT005023: Exception handling request to /modeshape-test/rest/test: org.jboss.resteasy.spi.UnhandledException: org.modeshape.jcr.cache.NodeNotFoundInParentException: Cannot locate child node: 0e0469894a0426a122c5b9-3b1e-42c1-be83-36669f6e2486 within parent: 0e0469894a0426afe30b1e-dd27-4a27-b48e-f2d7e1583992
        at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:76)
        at org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:212)
        at org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:168)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:411)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:202)
        at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:221)
        at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
        at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85)
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
        at net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:201)
        at net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:178)
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:60)
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
        at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
        at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
        at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
        at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131)
        at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
        at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
        at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
        at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
        at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)
        at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:284)
        at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
        at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
        at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
        at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
        at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
      Caused by: org.modeshape.jcr.cache.NodeNotFoundInParentException: Cannot locate child node: 0e0469894a0426a122c5b9-3b1e-42c1-be83-36669f6e2486 within parent: 0e0469894a0426afe30b1e-dd27-4a27-b48e-f2d7e1583992
        at org.modeshape.jcr.cache.document.LazyCachedNode.parentReferenceToSelf(LazyCachedNode.java:238)
        at org.modeshape.jcr.cache.document.LazyCachedNode.getSegment(LazyCachedNode.java:268)
        at org.modeshape.jcr.AbstractJcrNode.segment(AbstractJcrNode.java:248)
        at org.modeshape.jcr.JcrNode.getName(JcrNode.java:61)
        at com.ditemis.logic.TestNodeManager.buildTestNode(TestNodeManager.java:38)
        at com.ditemis.logic.TestNodeManager$Proxy$_$$_WeldClientProxy.buildTestNode(Unknown Source)
        at com.ditemis.rs.TestService.getNewTestNode(TestService.java:21)
        at com.ditemis.rs.TestService$Proxy$_$$_WeldClientProxy.getNewTestNode(Unknown Source)
        at sun.reflect.GeneratedMethodAccessor21.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:497)
        at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:139)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:236)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:395)
        ... 38 more
      

       

      We could only reproduce this error if there are update-operations on the same parent node running concurrently.

      I couldn't reproduce it when running the tests with my local development machine acting as server and client.

      The best way to reproduce the error for us was to run jmeter from two clients against one dedicated server - sadly it still doesn't always show up, just in some runs (you may experiment with ramp-up time and thread amount).

      As the tests run forever: The errors should occur after ~10.000 transactions or ~5:00 minutes runtime.

      To run the tests in your environment, you'll probably need to adjust the serverUrl and serverPort in the "Global vars" configuration.

       

      The test case uses the h2 database as the data source.

      We could also reproduce this error using an Oracle database.

       

      The error pattern seems to match the issue

      https://issues.jboss.org/browse/MODE-2617

      but we aren't using versionable nodes or clustering at the moment.

       

      Do you have an explanation for this behaviour?

      Are you able to reproduce the described behaviour with the provided test case?

       

      Thanks for your help!