12 Replies Latest reply on Mar 18, 2009 1:26 PM by Peter Johnson

    100% CPU usage with lots of memory

    Dean Pullen Novice

      Hi all,

      We've got an application that stores a large amount of data in-memory which is then used by a lot of users.

      Subsequently we're seeing CPU usage go through the use, and every now and then hit 100% (on a quad core machine with 8GB of mem) which I believe is when the JVM tries to garbage collect. The web app can't be used until JBoss is killed and restarted.

      We currently have these JVM opts:
      JAVA_OPTS="$JAVA_OPTS -Xms5g -Xmx5g -XX:MaxNewSize=3g -XX:PermSize=512m -XX:MaxP
      ermSize=1g -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterv
      al=3600000 -Djava.awt.headless=true -d64 -verbose:gc"

      Which may or may not be causing the problems - my knowledge of GC management is very limited.


      We see something similar to this in the logs:

      [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor451]
      [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor24]
      [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor450]
      [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor458]

      (lots more)

      [Full GC 4077824K->4077824K(4660352K), 7.6307480 secs]
      [Full GC 4077824K->4077625K(4660352K), 10.7810720 secs]
      [Full GC 4077823K->4077823K(4660352K), 7.6245730 secs]
      [Full GC 4077823K->4077611K(4660352K), 10.8113030 secs]

      (lots more)

      Any help would be much appreciated.

      JBoss 4.2.1GA
      SuSE Enterprise 10 SP1
      Java 1.6.0_05


        • 1. Re: 100% CPU usage with lots of memory
          Peter Johnson Master

          With those heap setting, the JVM will always do a full collection, which you noticed. The reason why: the JVM assumes the worst - that all objects in the young generation will survive the collection. Thus all 3GB of the young gen objects will survive, but according to your settings there is only 2GB available (5GB heap - 3GB young gen), thus a full colleciton is required.

          I recommend setting the MaxNewSize to a much smaller value, such as 200MB-400MB. It looks like your collections are never freeing more than about 200MB anyway.

          If I understand your app correctly, it allocates a lot of objects and then keeps them in memory. Those objects will, after a few collections, reside in the old generation. From that point on, the only objects in the young generation will be temporary objects which you want to have cleaned up with a minor collection.

          • 2. Re: 100% CPU usage with lots of memory
            Dean Pullen Novice

            PeterJ, I very much appreciate your response. I think you've hit the nail on the head too.

            I'll ensure we do this on the server ASAP and see what we results occur.

            What I don't really understand, is that we were having similar problems when the MaxNewSize was at default, which I believe is 32mb-ish?

            • 3. Re: 100% CPU usage with lots of memory
              Peter Johnson Master

              You might have to try several heap settings, and use -XX:+PrintHeapAtGC to get the GC details, which you should graph and then analyze. That should tell you what to set the heap to.

              Also, set -XX:NewSize the same as MaxNewSize.

              • 4. Re: 100% CPU usage with lots of memory
                Dean Pullen Novice

                Ok so we've had this running for around 12 hours+ and we're seeing similar issues.

                Receiving the following (over and over):

                [GC 2515286K->2130638K(5238528K), 0.0748890 secs]
                [GC 2515406K->2137619K(5237440K), 0.0824530 secs]
                [GC 2521619K->2144601K(5237312K), 0.0933110 secs]
                [GC 2528601K->2151535K(5236608K), 0.0912180 secs]
                [GC 2533231K->2151543K(5237120K), 0.0885810 secs]
                


                Using the settings you suggested:
                JAVA_OPTS="$JAVA_OPTS -Xms5g -Xmx5g -XX:MaxNewSize=384m -XX:NewSize=384m -XX:Per
                mSize=512m -XX:MaxPermSize=1g -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.
                dgc.server.gcInterval=3600000 -Djava.awt.headless=true -d64 -verbose:gc"
                


                After some time, the CPU was sticking around 50% (even when there was no activity) then during the time above it rose to 75% and seems to be stuck there...see JConsole output here:
                http://www.allstarconsultants.com/jconsole1.jpg

                Any further help would be appreciated :-/

                • 5. Re: 100% CPU usage with lots of memory
                  Dean Pullen Novice

                  And now this, only some minutes after a restart:

                  [Unloading class sun.reflect.GeneratedMethodAccessor750]
                   5015999K->5004634K(5126528K), 15.0047050 secs]
                  [19 Mar 2008 14:00:38] ERROR org.apache.catalina.core.ContainerBase.[jboss.web].[localhost].[/csi].[default] - Servlet.service() for servlet default threw exception
                  java.lang.OutOfMemoryError: GC overhead limit exceeded
                   at org.hibernate.util.ArrayHelper.slice(ArrayHelper.java:114)
                   at org.hibernate.type.ComponentType.hydrate(ComponentType.java:559)
                   at org.hibernate.type.ComponentType.nullSafeGet(ComponentType.java:275)
                   at org.hibernate.loader.Loader.getKeyFromResultSet(Loader.java:1097)
                   at org.hibernate.loader.Loader.getRowFromResultSet(Loader.java:565)
                   at org.hibernate.loader.Loader.doQuery(Loader.java:701)
                   at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236)
                   at org.hibernate.loader.Loader.doList(Loader.java:2220)
                   at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2104)
                   at org.hibernate.loader.Loader.list(Loader.java:2099)
                   at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:378)
                   at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338)
                   at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172)
                   at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121)
                   at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
                   at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:66)
                   at com.msp.ejb.csi.admin.performancereport.scoring.persistance.ScoringSessionFacadeBean.getAllDealerPerfRepQuestionSectionCopies(ScoringSessionFacadeBean.java:141)
                   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 org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112)
                   at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166)
                   at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63)
                   at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
                   at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54)
                   at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
                   at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
                   at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
                   at org.jboss.aspects.tx.TxPolicy.invokeInCallerTx(TxPolicy.java:126)
                   at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:195)
                   at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
                  [Full GC 5015999K->5001537K(5126528K), 10.3796170 secs]
                  [Full GC 5015999K->5005969K(5126528K), 10.3035780 secs]
                  [Full GC[Unloading class sun.reflect.GeneratedMethodAccessor704]
                  [Unloading class sun.reflect.GeneratedMethodAccessor708]
                  [Unloading class sun.reflect.GeneratedMethodAccessor702]
                  [Unloading class sun.reflect.GeneratedMethodAccessor703]
                  [Unloading class sun.reflect.GeneratedMethodAccessor705]
                  [Unloading class sun.reflect.GeneratedMethodAccessor707]
                  [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor256]
                   5015999K->5010260K(5126528K), 10.3110000 secs]
                  [Full GC[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor252]
                  


                  • 6. Re: 100% CPU usage with lots of memory
                    Peter Johnson Master

                    The set of GC output you posted at 9:37 looks good. Earlier, all of your GCs were full GCs taking around 10 seconds. Now you have minor GCs taking less than 1/10th of a second.

                    Your post at 10:02 shows that you have overrun the 5GB heap you set. Note the heap sizes both before and after the collection are around 5GB.

                    Now you have to find out why the amount of heap in use jumped from 2.5GB in the 9:37 posting to 5GB in the 10:02 posting. Look at the GC outputs for where the heap sizes started to increase and find out what was going on at that time. If the increase is a jump, then something changed, find out what it was. If the increase was gradual, I would suspect a memory leak.

                    Add -XX:+PrintGCTimestamps to the JVM options - this will let you know when each GC was done (amount of time since the app started).

                    • 7. Re: 100% CPU usage with lots of memory
                      Dean Pullen Novice

                      Thanks Peter - I'll do both.

                      • 8. Re: 100% CPU usage with lots of memory
                        Dean Pullen Novice

                        Seeing 99% CPU but not much memory being used + not much GC being performed and after a while saw these messages (multiple of):

                        [19 Mar 2008 17:06:33] WARN com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action a0000cb:9c83:47e12b7d:2f4a aborting with 1 threads active!
                        [19 Mar 2008 17:06:33] WARN com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id a0000cb:9c83:47e12b7d:2f65 invoked while multiple threads active within it.
                        [19 Mar 2008 17:06:33] WARN com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action a0000cb:9c83:47e12b7d:2f65 aborting with 1 threads active!
                        


                        Is that related to the CPU usage, is some atomic process locking and causing the high usage?

                        • 9. Re: 100% CPU usage with lots of memory
                          Peter Johnson Master

                          You might ask about these messages in the JBoss Transactions forum.

                          Looks like the next step is to run with a profiler to find out where your app is spending its time.

                          • 10. Re: 100% CPU usage with lots of memory
                            Dean Pullen Novice

                            JProbe or something like that?

                            Here's an odd one.

                            [GC 1163367K->948282K(5163904K), 0.0733880 secs]
                            [GC 1201082K->1033885K(5172672K), 0.2795530 secs]
                            [GC 1286685K->1035001K(5100352K), 0.1752780 secs]
                            [GC 1215481K->1035389K(5136512K), 0.0123550 secs]

                            As usual GC ran - at 19:59 which produces a spike in CPU usage.
                            But oddly the memory usage also goes up massively and doesn't get collected after:


                            http://www.allstarconsultants.com/jconsole2.jpg

                            I'm trying to further my understanding of GC etc, whilst also ensuring this isn't a problem.

                            • 11. Re: 100% CPU usage with lots of memory
                              Qiang XU Newbie

                              Hello PeterJ,
                              I have exactly the same issue as you.what I have seen is that there are a lot of I/O operations under the following path:
                              "$JBOSS_HOME/server/default/data/tx-object-store/HashedActionStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction".
                              These I/O operations consumed a lot of CPU,because Jboss kept generating files under this path. Does anybody have idea of this?
                              Thanks a lot


                              Seeing 99% CPU but not much memory being used + not much GC being performed and after a while saw these messages (multiple of):

                              Code:

                              [19 Mar 2008 17:06:33] WARN com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.co
                              ordinator.CheckedAction_2] - CheckedAction::check - atomic action a0000cb:9c83:47e12b7d:2f4a abortin
                              g with 1 threads active!
                              [19 Mar 2008 17:06:33] WARN com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.co
                              ordinator.BasicAction_58] - Abort of action id a0000cb:9c83:47e12b7d:2f65 invoked while multiple thr
                              eads active within it.
                              [19 Mar 2008 17:06:33] WARN com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.co
                              ordinator.CheckedAction_2] - CheckedAction::check - atomic action a0000cb:9c83:47e12b7d:2f65 abortin
                              g with 1 threads active!



                              • 12. Re: 100% CPU usage with lots of memory
                                Peter Johnson Master

                                As I responded to DeanoUK, who had this same problem, you need to ask about this in the JBoss Transactions forum, or search that forum to see if DeanoUK already asked the question there and see what answer he(?) got.