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

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

kaape Sep 8, 2016 10:10 AM

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!

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

hchiorean Sep 9, 2016 1:20 AM (in response to kaape)

The only possible explanation for this behavior is a bug somewhere (obviously this is not the intended behavior)

That being said, there have been a couple of recent JIRAs around transactions that were fixed (MODE-2623, MODE-2627) which could alter the behavior. So ideally you could try running the test case with a local build of the latest master and see if the problem is still there.

If the problem persists with the latest codebase, you can feel free to log a JIRA. However, if I can't reproduce your test case locally or if the test case is too complicated to "work on" (which it might be since you're talking about 10k transactions) then there's not much we can do. If the test case could be simplified (taken out of Wildfly and converted to a local test case - we have a large number of those e.g. https://github.com/ModeShape/modeshape/blob/master/modeshape-performance-tests/src/test/java/org/modeshape/test/performance/InMemoryPerformanceTest.java#L288 ) then this would help a lot.

As an alternative, you can try investigating the problem locally in your environment and if you identify the issue you can create a PR with the fix which we're happy to review and integrate.
Actions