1 2 Previous Next 16 Replies Latest reply on Jul 31, 2007 5:55 AM by Adrian Sandor

    JBC 2 performance

    Adrian Sandor Newbie

      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.

        • 1. Re: JBC 2 performance
          Manik Surtani Master

          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

          • 2. Re: JBC 2 performance
            Adrian Sandor Newbie

            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

            • 3. Re: JBC 2 performance
              Adrian Sandor Newbie

              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)
              [...]

              • 4. Re: JBC 2 performance
                Manik Surtani Master

                 

                "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


                • 5. Re: JBC 2 performance
                  Adrian Sandor Newbie

                   

                  "manik.surtani@jboss.com" wrote:
                  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

                  • 6. Re: JBC 2 performance
                    Adrian Sandor Newbie

                     

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

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

                    • 7. Re: JBC 2 performance
                      Adrian Sandor Newbie

                      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.

                      • 8. Re: JBC 2 performance
                        Manik Surtani Master

                        what isolation level are you using?

                        • 9. Re: JBC 2 performance
                          Adrian Sandor Newbie

                           

                          "manik.surtani@jboss.com" wrote:
                          what isolation level are you using?

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

                          • 10. Re: JBC 2 performance
                            Adrian Sandor Newbie

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

                            Adrian

                            • 11. Re: JBC 2 performance
                              Manik Surtani Master

                              Sorry, yes, this is patched in CVS HEAD.

                              • 12. Re: JBC 2 performance
                                Adrian Sandor Newbie

                                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.

                                • 13. Re: JBC 2 performance
                                  Manik Surtani Master

                                  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

                                  • 14. Re: JBC 2 performance
                                    Adrian Sandor Newbie

                                    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!

                                    1 2 Previous Next