Modeshape loses nodes during concurrency
codeape Dec 11, 2012 2:08 AMHello,
We are playing around with Modeshape. Cool stuff.
However, it looks like there is a concurrency problem caused by we are doing something wrong or Modeshape is broken.
This is the code and other resources:
Our webapp
{code:java}package com.example.modeshape;
import java.util.Iterator;
import java.util.concurrent.atomic.AtomicInteger;
import javax.inject.Inject;
import javax.jcr.Node;
import javax.jcr.NodeIterator;
import javax.jcr.Property;
import javax.jcr.PropertyIterator;
import javax.jcr.Repository;
import javax.jcr.RepositoryException;
import javax.jcr.Session;
import javax.ws.rs.Consumes;
import javax.ws.rs.GET;
import javax.ws.rs.PUT;
import javax.ws.rs.Path;
import javax.ws.rs.PathParam;
import javax.ws.rs.Produces;
import org.codehaus.jettison.json.JSONArray;
import org.codehaus.jettison.json.JSONException;
import org.codehaus.jettison.json.JSONObject;
import org.infinispan.schematic.document.Json;
import com.sun.jersey.json.impl.provider.entity.JSONArrayProvider;
@Path("/")
public class ModeshapeService {
private final Repository _repository;
static AtomicInteger call = new AtomicInteger();
@Inject
public ModeshapeService(Repository repository) {
_repository = repository;
}
@Path("document/{path}")
@GET
@Produces("application/json")
public JSONObject getDocument(@PathParam("path") String path) throws Exception {
Session session = _repository.login("main");
Node rootNode = session.getRootNode();
Node node = rootNode.getNode(path);
JSONObject json = jsonify(node);
return json;
}
@Path("document/{path}/count")
@GET
@Produces("application/json")
public JSONObject count(@PathParam("path") String path)
throws Exception
{
Session session = _repository.login("main");
JSONObject json = new JSONObject();
try {
Node rootNode = session.getRootNode();
Node pnode = rootNode.getNode(path);
NodeIterator nodeIter = pnode.getNodes();
long size = nodeIter.getSize();
while (nodeIter.hasNext()) {
Node inode = nodeIter.nextNode();
System.out.println(inode.getPath());
NodeIterator subNodeIter = inode.getNodes();
size += subNodeIter.getSize();
while (subNodeIter.hasNext()) {
Node tnode = subNodeIter.nextNode();
System.out.println(tnode.getPath());
}
}
json.put("count", size);
} finally {
session.logout();
}
return json;
}
@Path("document/{path}")
@PUT
@Consumes("application/json")
@Produces("text/plain")
public String createDocument(@PathParam("path") String path, JSONObject json)
throws Exception
{
Integer incr = call.incrementAndGet();
long start = System.nanoTime();
Session session = _repository.login("main");
int i = 0;
try {
Node rootNode;
if (!session.getRootNode().hasNode(path)) {
rootNode = session.getRootNode().addNode(path);
} else {
rootNode = session.getRootNode().getNode(path);
}
Node numNode = rootNode.addNode(incr.toString());
for (;i < 10; i++) {
Node node = numNode.addNode(String.valueOf(i));
//session.getRootNode().addNode(path + "/" + incr.toString() + "/" + i);
node.setPrimaryType("nt:unstructured");
writeJsonToNode(json, node);
}
session.save();
//System.out.println("Doing PUT " + incr.toString());
} finally {
session.logout();
}
long end = System.nanoTime();
return String.format("Creating 10 nodes took %dms", (end - start) / 1000000);
}
private void writeJsonToNode(JSONObject json, Node node)
throws Exception {
Iterator keys = json.keys();
while (keys.hasNext()) {
String key = (String) keys.next();
Object object = json.get(key);
if (object instanceof JSONObject) {
Node child = node.addNode(key);
writeJsonToNode((JSONObject) object, child);
}
else if (object instanceof JSONArray) {
JSONArray array = (JSONArray) object;
for (int i = 0; i < array.length(); i++) {
Object item = array.get(i);
if (item instanceof JSONObject) {
Node itemNode = node.addNode(key);
writeJsonToNode((JSONObject) item, itemNode);
}
else {
// ToDo: create list
setProperty(node, key, item);
}
}
}
else {
setProperty(node, key, object);
}
}
}
private void setProperty(Node node, String key, Object object)
throws Exception {
if (object instanceof Long) {
node.setProperty(key, (Long)object);
} else if (object instanceof Integer) {
node.setProperty(key, (Integer)object);
} else if (object instanceof Double) {
node.setProperty(key, (Double)object);
} else if (object instanceof String) {
node.setProperty(key, (String)object);
} else if (object instanceof Boolean) {
node.setProperty(key, (Boolean)object);
} else {
throw new IllegalArgumentException();
}
}
private JSONObject jsonify(Node node)
throws RepositoryException, JSONException
{
NodeIterator nodes = node.getNodes();
JSONObject json = new JSONObject();
while (nodes.hasNext()) {
Node next = (Node) nodes.next();
NodeIterator nodes2 = node.getNodes(next.getName());
if (nodes2.getSize() > 1) {
JSONArray array = new JSONArray();
nodes.skip(nodes2.getSize() - 1);
while (nodes2.hasNext()) {
array.put(jsonify(nodes2.nextNode()));
}
json.put(next.getName(), array);
}
else {
json.put(next.getName(), jsonify(next));
}
}
PropertyIterator properties = node.getProperties();
while (properties.hasNext()) {
Property property = (Property) properties.next();
json.put(property.getName(), property.getString());
}
return json;
}
}{code}
Modeshape conf
{code}{
"name" : "example",
"jndiName" : "jcr/example",
"monitoring" : {
"enabled" : true
},
"workspaces" : {
"default" : "main",
"allowCreation" : true
},
"storage" : {
"cacheConfiguration" : "infinispan.xml",
"cacheName" : "example",
"transactionManagerLookup" = "org.infinispan.transaction.lookup.GenericTransactionManagerLookup",
"binaryStorage" : {
"directory" : "modeshape/binary",
"minimumBinarySizeInBytes" : 4096,
"type" = "file"
}
},
}{code}
Infinispan conf
{code:xml}<infinispan>
<namedCache name="example">
<transaction
transactionManagerLookupClass="org.infinispan.transaction.lookup.GenericTransactionManagerLookup"
transactionMode="TRANSACTIONAL"
lockingMode="OPTIMISTIC"/>
<loaders shared="true"
passivation="false"
preload="false">
<loader class="org.infinispan.loaders.bdbje.BdbjeCacheStore"
fetchPersistentState="true"
purgeOnStartup="false">
<properties>
<property name="location" value="/opt/modeshape/cache"/>
</properties>
</loader>
</loaders>
</namedCache>
</infinispan>{code}
We test this code by sending this piece of json to the web service (with cleard cache by deleting the berkeley db files etc.) with Apache Bench:
{code}{
"title": "Titulum",
"author": "Patrik",
"body": "Marie Söderqvist, vd för Livsmedelsföretagen, och Åke Rutegård, vd för Kött- och Charkföretagen, ger kommunerna skulden för att livsmedelsbutiker säljer färgat och förfalskat kött. Kommunernas livsmedelskontroller brister och staten borde därför ta över deras ansvar, skriver de i en debattartikel (Brännpunkt 22/11).\nDet Söderqvist och Rutegård ägnar sig åt här är att försöka skjuta ifrån sig ansvaret. Istället för att skylla ifrån sig behöver de ställa sig frågan varför chark- och livsmedelsföretagen brister i sitt ansvar. Regelverket markerar tydligt att egenkontroll är en förutsättning för att få driva livsmedelsverksamhet. Det är företagarna själva som ska se till att varorna inte är falska.\n\nKommunernas kontrollansvar handlar framför allt om att se till att livsmedel förvaras och hanteras på ett bra sätt. Det sker inga omfattande provtagningar vilket krävs för att upptäcka en sådan här avancerad brottslig verksamhet. Sådana provtagningar skulle kräva oerhörda resurser och bli otroligt kostsam för branschen.\n\nDet är dessutom fel att tro att livsmedelskontroller skulle bli effektivare bara för att staten tar över ansvaret. Så sent som 2010 riktade EU-kommissionen kritik mot Livsmedelsverkets kontrollverksamhet eftersom myndigheten för sällan vidtog åtgärder mot bristfälliga verksamheter.\n\nNär ansvaret skjuts uppåt går man miste om något viktigt: närheten. Det är den som ger kommunerna en god kännedom om det lokala näringslivet. Det är den som gör att inspektörer inte bara kan rycka ut med kort varsel utan också röra sig i butikerna i sin vardag.\n\nDetta väljer Söderqvist och Rutegård att bortse från. Istället hävdar de att kommunerna inte vill släppa ifrån sig ansvaret eftersom livsmedelskontrollerna är en intäktskälla. Detta stämmer inte. Ingen kommun går med vinst på sina livsmedelskontroller. Taxorna som företagen betalar täcker ofta bara en del av kommunernas kontrollverksamhet.\n\nKommunerna välkomnar att Livsmedelsverket utifrån sina revisioner ingriper i de fall då kommuner brister i sitt kontrolluppdrag. Men vid den här typen av brottsliga handlingar är det ointressant att diskutera vem som gör kontrollen bäst. Det som är viktigt är att hela livsmedelskontrollkedjan hjälps åt.\n\nHÅKAN SÖRMAN\n\nvd Sveriges Kommuner och Landsting\n",
"rating": 3.0,
"categorization" : {
"subject": [ "subject-01", "subject-02033" ],
"person": ["Håkan Sörman", "Marie Söderqvist"],
},
}{code}
When we send this json with a single threaded client there is no problem:
{code}>$ ab -T "application/json" -c 1 -n 1000 -u src/main/resources/json http://localhost:8080/document/snabel
This is ApacheBench, Version 2.3 <$Revision: 1373084 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests
Server Software: Jetty(8.1.8.v20121106)
Server Hostname: localhost
Server Port: 8080
Document Path: /document/snabel
Document Length: 29 bytes
Concurrency Level: 1
Time taken for tests: 27.630 seconds
Complete requests: 1000
Failed requests: 999
(Connect: 0, Receive: 0, Length: 999, Exceptions: 0)
Write errors: 0
Total transferred: 104008 bytes
Total body sent: 2669000
HTML transferred: 27008 bytes
Requests per second: 36.19 [#/sec] (mean)
Time per request: 27.630 [ms] (mean)
Time per request: 27.630 [ms] (mean, across all concurrent requests)
Transfer rate: 3.68 [Kbytes/sec] received
94.33 kb/s sent
98.01 kb/s total
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.0 0 0
Processing: 17 27 66.4 22 2031
Waiting: 17 27 66.4 22 2031
Total: 18 28 66.4 22 2031
Percentage of the requests served within a certain time (ms)
50% 22
66% 24
75% 25
80% 26
90% 30
95% 41
98% 67
99% 79
100% 2031 (longest request)
>$ curl http://localhost:8080/document/snabel/count
{"count":11000}
{code}
We get the expected amount of nodes (11000).
Then stop the web service and clear the cache then start the web service and run the same test but with multiple threads (16 in this case):
{code}>$ ab -T "application/json" -c 16 -n 1000 -u src/main/resources/json http://localhost:8080/document/snabel
This is ApacheBench, Version 2.3 <$Revision: 1373084 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests
Server Software: Jetty(8.1.8.v20121106)
Server Hostname: localhost
Server Port: 8080
Document Path: /document/snabel
Document Length: 29 bytes
Concurrency Level: 16
Time taken for tests: 19.845 seconds
Complete requests: 1000
Failed requests: 983
(Connect: 0, Receive: 0, Length: 983, Exceptions: 0)
Write errors: 0
Total transferred: 105017 bytes
Total body sent: 2669000
HTML transferred: 28017 bytes
Requests per second: 50.39 [#/sec] (mean)
Time per request: 317.523 [ms] (mean)
Time per request: 19.845 [ms] (mean, across all concurrent requests)
Transfer rate: 5.17 [Kbytes/sec] received
131.34 kb/s sent
136.51 kb/s total
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.1 0 2
Processing: 145 316 385.5 242 3620
Waiting: 145 316 385.5 242 3620
Total: 146 316 385.5 243 3621
Percentage of the requests served within a certain time (ms)
50% 243
66% 263
75% 277
80% 289
90% 388
95% 530
98% 780
99% 3192
100% 3621 (longest request)
>$ curl http://localhost:8080/document/snabel/count
{"count":6688}
{code}
Now we only find half of the nodes (6688). And this happens every time.
The only Exception we get is the following and it appears in both cases (for the first call to the web service):
{code}
2012-dec-06 11:07:29 org.modeshape.jcr.JcrRepository$RunningState bindIntoJndi
: Error while binding repository 'Polopoly' into JNDI at 'jcr/polopoly' : jcr is not bound
javax.naming.NameNotFoundException: jcr is not bound
at org.eclipse.jetty.jndi.local.localContextRoot.bind(localContextRoot.java:611)
at org.eclipse.jetty.jndi.local.localContextRoot.bind(localContextRoot.java:550)
at javax.naming.InitialContext.bind(InitialContext.java:400)
at org.modeshape.jcr.JcrRepository$RunningState.bindIntoJndi(JcrRepository.java:1515)
at org.modeshape.jcr.JcrRepository$RunningState.<init>(JcrRepository.java:1197)
at org.modeshape.jcr.JcrRepository$RunningState.<init>(JcrRepository.java:960)
at org.modeshape.jcr.JcrRepository.doStart(JcrRepository.java:352)
at org.modeshape.jcr.JcrRepository.login(JcrRepository.java:609)
at org.modeshape.jcr.JcrRepository.login(JcrRepository.java:578)
at org.modeshape.jcr.JcrRepository.login(JcrRepository.java:147)
at com.polopoly.modeshape.ModeshapeService.createDocument(ModeshapeService.java:93)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)
at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1480)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1411)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1360)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1350)
at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:538)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:716)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:263)
at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:178)
at com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:91)
at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:62)
at com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:118)
at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:113)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1307)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:453)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:560)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1072)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:382)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1006)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:255)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:154)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
at org.eclipse.jetty.server.Server.handle(Server.java:365)
at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:485)
at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:937)
at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:998)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:856)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240)
at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:628)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
at java.lang.Thread.run(Thread.java:680){code}
I have attached the code in modeshape-pp-test.tar.gz. You can run it by:
{code}mvn clean install
mvn jetty:run{code}
We wonder:
1. Why do nodes disappear (are we doing wrong or is it a bug)?
2. Why do we get a repository binding error?
Note: I have also tried using File chace instead of Berkely cache with the same result:
{code:xml}<infinispan>
<namedCache name="Polopoly">
<transaction
transactionManagerLookupClass="org.infinispan.transaction.lookup.GenericTransactionManagerLookup"
transactionMode="TRANSACTIONAL"
lockingMode="OPTIMISTIC"/>
<loaders shared="true"
passivation="false"
preload="false">
<loader
class="org.infinispan.loaders.file.FileCacheStore"
fetchPersistentState="true"
ignoreModifications="false"
purgeOnStartup="false">
<properties>
<property name="location" value="/opt/modeshape/cache"/>
</properties>
</loader>
</loaders>
</namedCache>
</infinispan>{code}
After starting with clean/empty cache i got this:
{code}ab -T "application/json" -c 16 -n 1000 -u src/main/resources/json http://localhost:8080/document/snabel
This is ApacheBench, Version 2.3 <$Revision: 1373084 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests
Server Software: Jetty(8.1.8.v20121106)
Server Hostname: localhost
Server Port: 8080
Document Path: /document/snabel
Document Length: 29 bytes
Concurrency Level: 16
Time taken for tests: 28.082 seconds
Complete requests: 1000
Failed requests: 907
(Connect: 0, Receive: 0, Length: 907, Exceptions: 0)
Write errors: 0
Total transferred: 105092 bytes
Total body sent: 2669000
HTML transferred: 28092 bytes
Requests per second: 35.61 [#/sec] (mean)
Time per request: 449.314 [ms] (mean)
Time per request: 28.082 [ms] (mean, across all concurrent requests)
Transfer rate: 3.65 [Kbytes/sec] received
92.82 kb/s sent
96.47 kb/s total
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.2 0 2
Processing: 58 447 460.0 297 3363
Waiting: 58 447 460.1 296 3363
Total: 59 448 460.1 297 3363
Percentage of the requests served within a certain time (ms)
50% 297
66% 318
75% 343
80% 368
90% 810
95% 1534
98% 1773
99% 2976
100% 3363 (longest request)
>$ curl http://localhost:8080/document/snabel/count
{"count":3729}{code}
Only 3729 nodes found.
Thank you in advance.
-
modeshape-pp-test.tar.gz 6.3 KB