JBC 2 performance

[aditsu]

I wrote some code that used JBC 1.4.1.SP3, then later I converted it to use JBC 2.0.0.CR2, and I noticed that at least a part of it is running MUCH slower. Like, an order of magnitude slower.

That part of the code is putting a lot of data in the cache. I ran it with a profiler and a debugger, and found that most time is spent in the SimpleEntry constructor (which is getting called over 16 million times in my snapshot).

A frequent call sequence is:
CacheLoaderInterceptor.createNodes -> findChild -> UnversionedNode.getChildrenMapDirect -> MapCopy -> SimpleEntry. There are a few nodes that have MANY children, and JBC seems to call getChildrenMapDirect() on them repeatedly, and it creates a new MapCopy every time, with a new SimpleEntry for every child.

I looked at the JBC 1.4.1 code, and there CacheLoaderInterceptor.createNodes calls AbstractNode.getChild which calls "get" directly from the children map, without creating thousands of extra objects.
I don't know the reason why UnversionedNode.getChildrenMapDirect now has to make a new MapCopy every time, but I can tell you it seriously affects performance.

[manik]

Thanks for this - getChildrenMapDirect() was really created as a temporary measure to map 1.4.x internal APIs.

Ideally calling code should not use this deprecated method, as there are better ways of doing this.

I've created a JIRA task for refactoring this - JBCACHE-1116

[aditsu]

Hi, I've just found a similar problem in CacheImpl: various methods (such as _put) call getDataDirect() on a node, which again does a MapCopy, and slows down the code a lot. This is with 2.0.0.CR3. Can you please check?

Thanks
Adrian

[aditsu]

Besides that, I also got a bunch of ConcurrentModificationException's while doing a multi-threaded benchmark just now:

java.util.ConcurrentModificationException
at java.util.HashMap$HashIterator.nextEntry(HashMap.java:841)
at java.util.HashMap$EntryIterator.next(HashMap.java:883)
at java.util.HashMap$EntryIterator.next(HashMap.java:881)
at org.jboss.cache.util.MapCopy.(MapCopy.java:40)
at org.jboss.cache.UnversionedNode.getDataDirect(UnversionedNode.java:205)
at org.jboss.cache.CacheImpl._remove(CacheImpl.java:2545)
at sun.reflect.GeneratedMethodAccessor21.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.jgroups.blocks.MethodCall.invoke(MethodCall.java:330)
at org.jboss.cache.interceptors.CallInterceptor.invoke(CallInterceptor.java:49)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
[...]

[manik]

"aditsu" wrote:
Hi, I've just found a similar problem in CacheImpl: various methods (such as _put) call getDataDirect() on a node, which again does a MapCopy, and slows down the code a lot. This is with 2.0.0.CR3. Can you please check?

http://jira.jboss.com/jira/browse/JBCACHE-1148

[aditsu]

http://jira.jboss.com/jira/browse/JBCACHE-1148

Awesome!

I decided to get JBossCache from CVS and try it. I haven't checked the performance, but I still got the concurrency problems:

java.util.ConcurrentModificationException
at java.util.HashMap$HashIterator.nextEntry(HashMap.java:841)
at java.util.HashMap$EntryIterator.next(HashMap.java:883)
at java.util.HashMap$EntryIterator.next(HashMap.java:881)
at java.util.Collections$UnmodifiableMap$UnmodifiableEntrySet$1.next(Collections.java:1347)
at java.util.Collections$UnmodifiableMap$UnmodifiableEntrySet$1.next(Collections.java:1349)
at org.jboss.cache.util.MapCopy.(MapCopy.java:40)
at org.jboss.cache.notifications.Notifier.copy(Notifier.java:611)
at org.jboss.cache.notifications.Notifier.notifyNodeModified(Notifier.java:236)
at org.jboss.cache.CacheImpl._remove(CacheImpl.java:2555)


What happens is that multiple threads are putting and removing keys in the same node, and the cache doesn't seem to like it.
This is not really related to the original message, should I start a new thread about it?

Thanks
Adrian

[aditsu]

"aditsu" wrote:
This is not really related to the original message

Hm.. or is it? I've just noticed the MapCopy in the trace

[aditsu]

Hm, Notifier.copy now thinks the data is unsafe (it's not a MapCopy instance anymore) so it makes a new copy. If I prevent that from happening, the ConcurrentModificationException goes away.

[manik]

what isolation level are you using?

[aditsu]

what isolation level are you using?

I think it was READ_COMMITTED (I can't see the code right now)

[aditsu]

So.. is this problem going to be solved?
Just in case you were waiting, I confirm that I'm using READ_COMMITTED

Adrian

[manik]

Sorry, yes, this is patched in CVS HEAD.

[aditsu]

Thanks, I updated from CVS and the first thing I found is a NPE:

java.lang.NullPointerException
at java.util.concurrent.ConcurrentHashMap.put(ConcurrentHashMap.java:846)
at java.util.concurrent.ConcurrentHashMap.putAll(ConcurrentHashMap.java:888)
at org.jboss.cache.UnversionedNode.putAllDirect(UnversionedNode.java:540)
at org.jboss.cache.CacheImpl._put(CacheImpl.java:2279)
at org.jboss.cache.CacheImpl._put(CacheImpl.java:2236)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
[...]

Apparently ConcurrentHashMap doesn't allow null values.

[manik]

Thanks for this - this stuff has actually led to finding a pretty critical bug in the PessimisticLockInterceptor which was previously hidden away due to excessive synchronization in the node.

See JBCACHE-1157

[aditsu]

Hm.. I'm not sure how it's related, but it sounds very good.

I updated again from CVS; it seems to work now and doesn't do MapCopy anymore. The performance is still not really great, but it may not be JBC's fault. I'll keep profiling.

Thanks for the good work!