More on infinispan connector performance

[craigching]

So I've enhanced my version of modeshape with my suggestion of replacing LinkedList with ArrayList in MapNode, performance has improved, but I still see JcrSession.save() taking more and more time as I add more nodes to the repository.  My goal is to get to tens of millions of nodes and test searching, but I can't really, practically yet get to 10's of thousands of nodes.

I've been trying to profile my application and I'm seeing, after about 10,000 nodes being added to my repository, that FederatedRequest.await() is taking ~72% CPU and continues to grow with each session.save().  I'm assuming something is going on on the other side of the countdown latch that is being used there where the other side is taking longer and longer before it decrements the latch, thus freeing up FederatedRequest.await().

I'll continue digging, but it's getting harder and harder for me to continue without some guidance, can anyone shed some light on what might be going wrong?  Or point me in the right direction?

My application is the same one that is posted here: http://community.jboss.org/message/560965#560965 except that I've changed it to create 50000 cars instead of 10.

[craigching]

I'm still digging into this, I've been sidetracked earlier this week, but I wanted to get this data point on the list in case anyone feels like helping me.  I've profiled ModeShape further and I'm finding a large number of calls to MapTransaction.findNode().  For every 100 new nodes that I save in the session, the number of calls to MapTransaction.findNode() goes up by 10,400.  It's very consistent.  Here's a table that shows the data:

Items saved in session	MapTransaction.findNode() invocations	Invocations this batch	Difference of invocations vs. last batch
+100 (100 total in repo)	14214
+100 (200)	19694	5480
+100 (300)	35563	15869	10389
+100 (400)	61843	26280	10411
+100 (500)	98523	36680	10400
+100 (600)	145603	47080	10400
+100 (700)	203083	57480	10400
+100 (800)	270963	67880	10400
+100 (900)	349243	78280	10400
+100 (1000)	437923	88680	10400
+100 (1100)	537003	99080	10400
+100 (1200)	646483	109480	10400
+100 (1300)	766374	119891	10411
+100 (1400)	896654	130280	10389
+100 (1500)	1037345	140691	10411
+100 (1600)	1188436	151091	10400
+100 (1700)	1349927	161491	10400
+100 (1800)	1521818	171891	10400
+100 (1900)	1704098	182280	10389
+100 (2000)	1896789	192691	10411
+100 (2100)	2099880	203091	10400

Again, here is my logic:

                Node root = session.getRootNode();

                for(int i = 0; i < 50000; ++i) {

                    Node entry = root.addNode("e_" + i, "entry:Entry");

                    entry.setProperty("entry:EVENTID", Integer.toString(i));

                    entry.setProperty("entry:USERNAME", users[i % users.length]);

                    entry.setProperty("entry:OBJECTNAME", objects[i % objects.length]);

                    entry.setProperty("entry:SERVERTIME", Calendar.getInstance());

                    if (i % 100 == 0) {

                        System.out.println("SAVED!!! (" + i + ") - [" + new SimpleDateFormat("HH:mm:ss.SSSZ").format(new Date()) + "]");

                        long begin = System.currentTimeMillis();

                        session.save();

                        long diff = System.currentTimeMillis() - begin;

                        System.out.println("==> Save took " + diff + " milliseconds.");

                    }

                }

                Node root = session.getRootNode();

                for(int i = 0; i < 50000; ++i) {

                    Node entry = root.addNode("e_" + i, "entry:Entry");

                    entry.setProperty("entry:EVENTID", Integer.toString(i));

                    entry.setProperty("entry:USERNAME", users[i % users.length]);

                    entry.setProperty("entry:OBJECTNAME", objects[i % objects.length]);

                    entry.setProperty("entry:SERVERTIME", Calendar.getInstance());

                    if (i % 100 == 0) {

                        System.out.println("SAVED!!! (" + i + ") - [" + new SimpleDateFormat("HH:mm:ss.SSSZ").format(new Date()) + "]");

                        long begin = System.currentTimeMillis();

                        session.save();

                        long diff = System.currentTimeMillis() - begin;

                        System.out.println("==> Save took " + diff + " milliseconds.");

                        System.out.println("Sleeping for 5 seconds");

                        Thread.sleep(15000);

                        System.out.println("Back awake and at it now.");

                    }

                }

Am I doing something wrong here?  It feels like maybe I'm misusing the JCR API or something.  Basically what I'm seeing is that every save of 100 new nodes invokes findNode n + 10400 where n = the previous number of findNodes invocations.

[rhauch]

Great work!

What version are you running against? We've made a number of improvements and optimizations to the MapTransaction and related classes. I'd be curious if that improved the results.

Also, your tests add all of the nodes under the root. Have you tried this same test when adding nodes at various levels?

[craigching]

I'm running against a trunk build from about 2 weeks ago, I'll do another build and test.  I can't seem to build on Windows where I'm running the test (maven craps out with an index out of bounds exception in referencing one of the assembly files, I don't see what the problem is), so I'll have to finish pulling on my mac and do a build there.

As for various levels, I haven't done that.  Our use case really has us at a depth of 1 mostly for the tree ... but now that I type that, I'm thinking that's not necessarily true.  In most cases it is true, but where we're going to have a lot of objects it probably isn't.  Let me set up a test like that and see too.

[rhauch]

If your project is Maven based, and you need to load the ModeShape artifacts into the repository, you don't need to do an assembly build. Instead, you could just use "mvn clean install" to build all the projects and install them into the local repository.  You could even build them without running the tests, with "mvn clean install -DskipTests=true".

However, if you instead need all of the JARs as files (and not in a Maven repository), then it's probably easier to just do an assembly build.

[craigching]

'mvn clean install' on the ModeShape projects does build the assemblies (I'm building all from the root pom). Unless there's a profile that I can invoke that will skip the modeshape assemblies ...  Anyway, no worries, I'm building on a Linux machine now, I should be able to test here very shortly.

[craigching]

I've simplified my tracking of this by adding a public static AtomicLong to the MapTransaction class and incrementing the AtomicLong for every findNode() invocation.  Then, just before my sessoin.save(), I reset it and then getAndReset() it right after session.save() finishes:

                        MapTransaction.invocations.getAndSet(0);

                        session.save();

                        curr_invocations = MapTransaction.invocations.getAndSet(0);

                        MapTransaction.invocations.getAndSet(0);

                        session.save();

                        curr_invocations = MapTransaction.invocations.getAndSet(0);

And what I'm seeing, with the current trunk, is that each session.save() will invoke MapTransaction.findNode() n + 10300 times where n == previous number of findNode() invocations.  So, the trunk is not really better with respect to this particular profiling point.  I will say this, though, it "feels" faster (wall time) than the previous build I was using, but it's hard to know for sure if it is or not because I've been living in the profiler for the past week and haven't run a test outside of it since ;-)

I'm going to start working on a test that more realistically mirrors how we will actually be using modeshape.  I still think this test is worth investigating, though, as it is quite conceivable that we could have large numbers of objects in a more "flat" hierarchy like this test.  So I may come back to this one at some point as well.

[rhauch]

Yeah, something is definitely wrong. Can you please log a bug in JIRA?

[craigching]

https://jira.jboss.org/browse/MODE-923

I will provide a complete project and a patch to include the way I counted the invocations.  It might not be until this weekend, though, so fair warning!  Thanks for helping with this Randall!

[rhauch]

Thanks, Craig, for helping out and being so thorough with your testing and reporting!

[craigching]

I was able to make some time over lunch to get a project and a diff for counting the findNode invocations done.  It's all in the JIRA issue.