-
1. Re: 100% CPU usage with lots of memory
peterj Mar 18, 2008 5:41 PM (in response to deanouk)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
deanouk Mar 18, 2008 5:57 PM (in response to deanouk)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
peterj Mar 18, 2008 6:03 PM (in response to deanouk)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
deanouk Mar 19, 2008 9:37 AM (in response to deanouk)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
deanouk Mar 19, 2008 10:02 AM (in response to deanouk)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
peterj Mar 19, 2008 11:52 AM (in response to deanouk)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
deanouk Mar 19, 2008 12:38 PM (in response to deanouk)Thanks Peter - I'll do both.
-
8. Re: 100% CPU usage with lots of memory
deanouk Mar 19, 2008 1:09 PM (in response to deanouk)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
peterj Mar 19, 2008 2:10 PM (in response to deanouk)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
deanouk Mar 19, 2008 4:16 PM (in response to deanouk)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
juvenxu Mar 18, 2009 11:18 AM (in response to deanouk)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
peterj Mar 18, 2009 1:26 PM (in response to deanouk)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.