Home.... | log in.... | Pub my question! | Sign-up....
Java-index >> Java HotSpot Virtual Machine >> Specifications

[Full GC] halts my application for 25 seconds

Hello, I need to avoid this happening. I have tried using

-XX:+UseParallelGC

and

-XX:+UseConcMarkSweepGC

.....with slightly differing results but at some point within the first 5 minutes of the application running, a 25 second full GC takes place that virtually halts the application.

I am using a T1000 that has 24 core chip (i.e. 24 threads) with solaris 10. I am using jvm hotspot 1.5.

My application is not typical, the first thing it does is load a serialized object that is approximately 1GB in size. This object lives for the entire application. Then 20 threads are started which do all sorts of computation where the object is used as a read only database. (just in case you are a T1000 expert I do not do any floating point arithmetic which would be a bottleneck on the T1000)

I am using the 32 bit JVM since when I switched to 64 bit JVM the application slowed down by about 30%. I can get a max heap size of 4GB on solaris 10 using the 32 bit JVM but a 2GB heap size is sufficient to run my application. Even when I set the heap size to 4GB I still get a 25 second FULL GC delay.

I believe my large object is being loaded somewhere in the heap and then subsequently moved and maybe this is causing the problem? (not sure)

The threads use mostly global and local variables. Very few new objects are created on the fly.

Any guidance would be much appreciated.

For the record -XX:+UseConcMarkSweepGC is slightly better then -XX:+UseParallelGC in my application when using the default JVM values.

[1579 byte] By [driving_me_nutsa] at [2007-11-26 17:53:16]
«« I have a binary string. Now I need the binary number
»» system default netmask changes after cluster installation
# 1

> I believe my large object is being loaded somewhere

> in the heap and then subsequently moved and maybe

> this is causing the problem? (not sure)...

Your assumption is right. Your object gets first allocated in eden, then it is moved to the old generation space (via the two equally-sized survivor spaces in Solaris).

Hotspot makes a number of assumptions about how objects are used in most applications. The main underlying assumption is that most objects will have a short lifespan. From what you're describing, this is obviously not your case.

I would suggest to try using first the incremental gc (-Xincgc) to try to spread the major collection into several smaller ones. If that does not work out, try -XX:+AggressiveHeap. That option will run -XX:+UseParallelGC along with adaptive sizing -XX:+UseAdaptiveSizePolicy. That last option will help you make decisions regarding the respective sizes of new and old generation space (use -verbose:gc ).

The best solution (and probably the most painful) would be to redesign your application and do allocation in chunks.

karma-9a at 2007-7-9 5:06:16 > top of Java-index,Java HotSpot Virtual Machine,Specifications...
# 2

Thanks for advice. I don't think incremental will help since my app stops when the CMS is doing a parallel rescan, this is not a concurrent phase and so the incremental mode will not help. Here is the output when my app is halted for 40 seconds or so:

349.460: [CMS-concurrent-abortable-preclean: 219.904/228.871 secs]

349.468: [GC[YG occupancy: 37335 K (73664 K)]349.468: [Rescan (parallel)

I am flogging a dead horse here? If I have a single object that is 1GB in size and I know it is long lived is there anyway of bypassing Eden and get the object straight into the Tenured area.

I'll try your other suggestion.

driving_me_nutsa at 2007-7-9 5:06:16 > top of Java-index,Java HotSpot Virtual Machine,Specifications...
# 3

I ran my application with flags

-server -XX:+AggressiveHeap -XX:+PrintTenuringDistribution

-verbosegc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps

The output is given below

I still get FULL GC at regular intervals (471.920, 3146.709, 5820.270) where my entire application hanges for 40 to 50 seconds. During this time other servers drop connections to my server since they do not receive any heartbeat messages. It is a real problem. Any ideas?

0.000: [GC [PSYoungGen: 1087453K->180802K(1268736K)] 1087453K->701012K(3685376K), 4.4110619 secs]

465.165: [GC [PSYoungGen: 1268290K->180763K(1268736K)] 1788500K->1612425K(3685376K), 6.7550747 secs]

471.920: [Full GC [PSYoungGen: 180763K->0K(1268736K)] [PSOldGen: 1431662K->1611699K(2416640K)] 1612425K->1611699K(3685376K) [PSPermGen: 9432K->9432K(20480K)], 27.7722229 secs]

3146.709: [Full GC [PSYoungGen: 1087488K->0K(1268736K)] [PSOldGen: 1611699K->1611737K(2416640K)] 2699187K->1611737K(3685376K) [PSPermGen: 9449K->9449K(24576K)], 28.2615399 secs]

5820.270: [Full GC[Unloading class sun.reflect.GeneratedMethodAccessor8]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor11]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor9]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor23]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor12]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor30]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor35]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor13]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor15]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor17]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor22]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor28]

[Unloading class sun.reflect.GeneratedMethodAccessor10]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor10]

[Unloading class sun.reflect.GeneratedConstructorAccessor5]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor6]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor33]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor27]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor21]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor18]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor2]

[Unloading class sun.reflect.GeneratedMethodAccessor4]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor20]

[Unloading class sun.reflect.GeneratedMethodAccessor5]

[Unloading class sun.reflect.GeneratedMethodAccessor2]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor4]

[Unloading class sun.reflect.GeneratedMethodAccessor7]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor19]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor3]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor8]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor14]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor7]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor16]

[Unloading class sun.reflect.GeneratedMethodAccessor3]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor34]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor1]

[Unloading class sun.reflect.GeneratedMethodAccessor11]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor29]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor36]

[Unloading class sun.reflect.GeneratedMethodAccessor13]

[Unloading class sun.reflect.GeneratedConstructorAccessor4]

[Unloading class sun.reflect.GeneratedMethodAccessor12]

[Unloading class sun.reflect.GeneratedMethodAccessor14]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor5]

[Unloading class sun.reflect.GeneratedMethodAccessor6]

[Unloading class sun.reflect.GeneratedMethodAccessor9]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor32]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor24]

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor31]

[PSYoungGen: 1087488K->0K(1268736K)] [PSOldGen: 1611737K->1611770K(2416640K)] 2

699225K->1611770K(3685376K) [PSPermGen: 9455K->9455K(24576K)], 28.2561766 secs]

driving_me_nutsa at 2007-7-9 5:06:16 > top of Java-index,Java HotSpot Virtual Machine,Specifications...
# 4

You don't say what your heap sizing parameters are, but from 471.920: [Full GC [PSYoungGen: 180763K->0K(1268736K)]

[PSOldGen: 1431662K->1611699K(2416640K)] 1612425K->1611699K(3685376K)

[PSPermGen: 9432K->9432K(20480K)], 27.7722229 secs]

it looks like you have a 3600MB heap with 1240MB in the young generation. That leaves you about 2400MB in the old generation. And as you say, you have 1.5GB of live data, which all ends up in the old generation when this collection is over. Now look at the tuning guide for the "Young Generation Guarantee" (http://java.sun.com/docs/hotspot/gc5.0/gc_tuning_5.html#0.0.0.0.%20Young%20Generation%20Guarantee%7Coutline), and notice that you don't have room in the old generation for your live data plus a full promotion from the young generation. (Especially for an application that has the occasional 1GB object that has to be promoted!) So the collector would be justified in not trying a young generation collection (even though it might work), and instead just does a full collection. You could try making your young generation smaller since those collections are few and far between, and once you get your long-lived data into the old generation they might even be speedy. (You might also find that a young generation smaller than your huge object would force the huge object to be allocated directly in the old generation, saving you a bunch of promotion time. But that's secondary to getting away from the full collections.

On the other hand, I look at the time stamps between your full collections: 3146.709-471.920=2674.789 and 5820.270-3146.709=2673.561 and wonder why those are so regular. Might you be calling System.gc() at regular intervals? That would be another good reason for the collector to do a full collection. You could try running with -XX:+DisableExplicitGC, which turns calls to System.gc() into a no-op. That might help, unless for some reason you need the full collections (e.g., for RMI's distributed garbage collection algorithm). If you are running the CMS collector, there's a flag, -XX:+ExplicitGCInvokesConcurrent, to make calls to System.gc() start a concurrent collection. That might be less disruptive.

Why are you using -XX:+AggressiveHeap? Do you know what that does? (Try running with -XX:+PrintCommandLineFlags to find out.) That sets the heap for applications that don't care about pause times, as you seem to. (That may also be why your generations are sized the way they are, even though that's the wrong partitioning for the amount of live data you have.)

Fix your heap shaping and see if you are calling System.gc() and please report back by posting more logs on this thread. Thanks.

PeterKesslera at 2007-7-9 5:06:16 > top of Java-index,Java HotSpot Virtual Machine,Specifications...
# 5

Thanks for the reply.I hope you had a good weekend.

I do not make any System.gc() calls I think the regular interval between FULL GC is due to the fact that my application is running in a test cycle where all 20 threads are continuosly running doing the same algorithm over and over again. At some point one of the generations runs out of heap space and a FULL GC takes place.

I tried the -XX:+AggressiveHeap option on recommendation of an earlier post to this thread to obtain extra info on what the application demanded of the heap?

I have tried running with -XX:+UseConcMarkSweepGC and -XX:+UseParallelGC while setting the min heap size equal to the max heap size and setting the -XX:+NewRatio=8 to force the young generation to be small. However I still get the FULL GC or a [rescan parallel] for CMS.

For example running with (UseConcMarkSweepGC ):

java -server -verbosegc -XX:+PrintCommandLineFlags -XX:+UseConcMarkSweepGC -XX:+PrintTenuringDistribution -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xms2000M -Xmx2000M -XX:NewRatio=8

I get the following output:

-XX:InteriorEntryAlignment=4 -XX:MaxHeapSize=2097152000 -XX:NewRatio=8 -XX:OptoLoopAlignment=4 -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:+TraceClassUnloading -XX:+UseConcMarkSweepGC -XX:-UseInlineCaches

0.000: [GC 0.000: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.2176081 secs] 73600K->22534K(2047936K), 0.2181019 secs]

4.149: [GC 4.150: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 68197K->0K(73664K), 0.2785933 secs] 90731K->57331K(2047936K), 0.2789286 secs]

9.336: [GC 9.336: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.2794852 secs] 130931K->89278K(2047936K), 0.2798072 secs]

13.400: [GC 13.400: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.3200039 secs] 162878K->133893K(2047936K), 0.3203428 secs]

19.254: [GC 19.255: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.2713734 secs] 207493K->163554K(2047936K), 0.2716955 secs]

25.497: [GC 25.497: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.2867734 secs] 237154K->193521K(2047936K), 0.2871141 secs]

28.866: [GC 28.866: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 56577K->0K(73664K), 0.4515038 secs] 250098K->234575K(2047936K), 0.4518424 secs]

38.182: [GC 38.183: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.4806463 secs] 308175K->289473K(2047936K), 0.4809833 secs]

46.551: [GC 46.551: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 72433K->0K(73664K), 0.3772204 secs] 361907K->336201K(2047936K), 0.3775806 secs]

47.098: [GC 47.098: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 72651K->0K(73664K), 0.3579717 secs] 408852K->403839K(2047936K), 0.3583320 secs]

47.669: [GC 47.669: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 64914K->0K(73664K), 0.5123982 secs] 468754K->465760K(2047936K), 0.5127820 secs]

48.301: [GC 48.301: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.4507056 secs] 539360K->538494K(2047936K), 0.4510840 secs]

48.877: [GC 48.878: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73569K->0K(73664K), 0.5563776 secs] 612064K->611072K(2047936K), 0.5567737 secs]

49.548: [GC 49.548: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.5505671 secs] 684672K->684312K(2047936K), 0.5509652 secs]

50.149: [GC 50.149: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.5351971 secs] 757912K->757699K(2047936K), 0.5355758 secs]

50.751: [GC 50.751: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73571K->0K(73664K), 0.4926143 secs] 831270K->830675K(2047936K), 0.4929750 secs]

51.307: [GC 51.308: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73596K->0K(73664K), 0.5299406 secs] 904271K->903863K(2047936K), 0.5303016 secs]

51.898: [GC 51.898: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73588K->0K(73664K), 0.5263566 secs] 977451K->977208K(2047936K), 0.5267523 secs]

52.489: [GC 52.489: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73597K->0K(73664K), 0.5252043 secs] 1050805K->1050670K(2047936K), 0.5255898 secs]

53.019: [GC [1 CMS-initial-mark: 1050670K(1974272K)] 1050716K(2047936K), 0.2034301 secs]

53.223: [CMS-concurrent-mark-start]

53.296: [GC 53.296: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73571K->0K(73664K), 0.4967965 secs] 1124242K->1124172K(2047936K), 0.4971631 secs]

53.850: [GC 53.850: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73591K->0K(73664K), 0.5298101 secs] 1197763K->1196930K(2047936K), 0.5302043 secs]

54.663: [GC 54.663: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73567K->0K(73664K), 0.4981155 secs] 1270497K->1270431K(2047936K), 0.4985203 secs]

55.444: [GC 55.444: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73587K->0K(73664K), 0.5251508 secs] 1344018K->1343971K(2047936K), 0.5255248 secs]

56.257: [GC 56.257: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73585K->0K(73664K), 0.4963938 secs] 1417557K->1417511K(2047936K), 0.4967661 secs]

57.063: [GC 57.064: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73587K->0K(73664K), 0.5404960 secs] 1491099K->1491052K(2047936K), 0.5408666 secs]

57.889: [GC 57.890: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73587K->0K(73664K), 0.5276985 secs] 1564639K->1564592K(2047936K), 0.5280607 secs]

58.700: [GC 58.700: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73585K->0K(73664K), 0.5030686 secs] 1638178K->1638133K(2047936K), 0.5034285 secs]

70.229: [GC 70.230: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.6700260 secs] 1711733K->1708413K(2047936K), 0.6704053 secs]

109.777: [CMS-concurrent-mark: 51.649/56.554 secs]

109.777: [CMS-concurrent-preclean-start]

123.257: [CMS-concurrent-preclean: 13.201/13.480 secs]

123.257: [CMS-concurrent-abortable-preclean-start]

242.070: [GC 242.070: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.3301932 secs] 1782013K->1708467K(2047936K), 0.3305548 secs]

332.453: [CMS-concurrent-abortable-preclean: 200.699/209.195 secs]

332.468: [GC[YG occupancy: 38454 K (73664 K)]332.468: [Rescan (parallel) , 41.45

33178 secs]373.921: [weak refs processing, 0.0047086 secs] [1 CMS-remark: 170846

7K(1974272K)] 1746921K(2047936K), 41.4585277 secs]

373.926: [CMS-concurrent-sweep-start]

375.838: [CMS-concurrent-sweep: 1.911/1.911 secs]

375.839: [CMS-concurrent-reset-start]

376.264: [CMS-concurrent-reset: 0.425/0.425 secs]

378.278: [GC [1 CMS-initial-mark: 1610059K(1974272K)] 1650825K(2047936K), 0.5755228 secs]

378.854: [CMS-concurrent-mark-start]

407.269: [CMS-concurrent-mark: 28.415/28.415 secs]

407.269: [CMS-concurrent-preclean-start]

411.336: [CMS-concurrent-preclean: 3.916/4.066 secs]

411.336: [CMS-concurrent-abortable-preclean-start]

455.698: [GC 455.699: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.2800689 secs] 1683659K->1610105K(2047936K), 0.2804480 secs]

543.952: [CMS-concurrent-abortable-preclean: 126.992/132.616 secs]

543.960: [GC[YG occupancy: 37646 K (73664 K)]543.960: [Rescan (parallel) , 43.59

17975 secs]587.552: [weak refs processing, 0.0006659 secs] [1 CMS-remark: 161010

5K(1974272K)] 1647752K(2047936K), 43.5931453 secs]

587.553: [CMS-concurrent-sweep-start]

589.414: [CMS-concurrent-sweep: 1.859/1.860 secs]

589.414: [CMS-concurrent-reset-start]

589.836: [CMS-concurrent-reset: 0.422/0.422 secs]

668.077: [GC 668.078: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.3062407 secs] 1683328K->1609823K(2047936K), 0.3066149 secs]

837.928: [GC 837.928: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.3142065 secs] 1683423K->1609871K(2047936K), 0.3145773 secs]

1006.828: [GC 1006.829: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.2990423 secs] 1683471K->1609916K(2047936K), 0.2994262 secs]

1176.190: [GC 1176.190: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.2841302 secs] 1683516K->1609961K(2047936K), 0.2845103 secs]

1345.957: [GC 1345.958: [ParNew

Desired survivor size 32768 bytes, new threshold 0 (max 0)

: 73600K->0K(73664K), 0.2815574 secs] 1683561K->1610004K(2047936K), 0.2819370 secs]

Note the "rescan parallel" that halt my entire app for 40 seconds

When running with the following options: (UseParallelGC):

java -server -verbosegc -XX:+PrintCommandLineFlags -XX:+UseParallelGC -XX:+PrintTenuringDistribution -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xms2000M -Xmx2000M -XX:NewRatio=8

-XX:InteriorEntryAlignment=4 -XX:MaxHeapSize=2097152000 -XX:NewRatio=8 -XX:OptoLoopAlignment=4 -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:+TraceClassUnloading -XX:-UseInlineCaches -XX:+UseParallelGC

0.000: [GC [PSYoungGen: 172032K->28660K(200704K)] 172032K->61307K(2023424K), 0.6313472 secs]

10.883: [GC [PSYoungGen: 200692K->28667K(200704K)] 233339K->131975K(2023424K), 0.8443841 secs]

22.509: [GC [PSYoungGen: 188715K->28656K(200704K)] 292023K->214207K(2023424K), 0.9055289 secs]

39.892: [GC [PSYoungGen: 200688K->28665K(200704K)] 386239K->332817K(2023424K), 0.8174915 secs]

41.107: [GC [PSYoungGen: 200697K->28666K(200704K)] 504849K->503928K(2023424K), 0.8707069 secs]

42.149: [GC [PSYoungGen: 200698K->28668K(105216K)] 675960K->674945K(1927936K), 1.5950903 secs]

43.815: [GC [PSYoungGen: 105180K->76407K(152960K)] 751457K->751471K(1975680K), 1.3401893 secs]

45.217: [GC [PSYoungGen: 152916K->76411K(152960K)] 827981K->827888K(1975680K), 1.1669644 secs]

46.447: [GC [PSYoungGen: 152946K->76402K(152960K)] 904424K->904148K(1975680K), 1.0126673 secs]

47.529: [GC [PSYoungGen: 152908K->76410K(152960K)] 980654K->979426K(1975680K), 0.6437828 secs]

48.245: [GC [PSYoungGen: 152929K->76341K(152960K)] 1055946K->1055692K(1975680K), 0.6637935 secs]

48.977: [GC [PSYoungGen: 152868K->76380K(152960K)] 1132219K->1132013K(1975680K), 0.6369726 secs]

49.677: [GC [PSYoungGen: 152887K->76380K(152960K)] 1208520K->1208413K(1975680K), 0.6685147 secs]

50.409: [GC [PSYoungGen: 152920K->76380K(152960K)] 1284953K->1284851K(1975680K), 0.6538527 secs]

51.135: [GC [PSYoungGen: 152895K->76380K(152960K)] 1361367K->1361290K(1975680K), 0.6444856 secs]

51.847: [GC [PSYoungGen: 152911K->76380K(152960K)] 1437821K->1437768K(1975680K), 0.6756490 secs]

52.587: [GC [PSYoungGen: 152899K->76380K(152960K)] 1514287K->1514245K(1975680K), 0.6632129 secs]

53.319: [GC [PSYoungGen: 152898K->76380K(152960K)] 1590764K->1590723K(1975680K), 0.6504621 secs]

54.035: [GC [PSYoungGen: 152911K->76412K(152960K)] 1667254K->1667194K(1975680K), 0.6742812 secs]

156.908: [GC [PSYoungGen: 152956K->29408K(152960K)] 1743738K->1696456K(1975680K), 0.7538557 secs]

322.180: [GC [PSYoungGen: 105952K->48K(152960K)] 1773000K->1696328K(1975680K), 0.6638129 secs]

322.844: [Full GC [PSYoungGen: 48K->0K(152960K)] [PSOldGen: 1696280K->1610398K(1822720K)] 1696328K->1610398K(1975680K) [PSPermGen: 9450K->9450K(20480K)], 31.0423115 secs]

518.622: [GC [PSYoungGen: 76544K->96K(152960K)] 1686942K->1610494K(1975680K), 0.5657313 secs]

682.438: [GC [PSYoungGen: 76640K->96K(152960K)] 1687038K->1610542K(1975680K), 0.5576964 secs]

848.107: [GC [PSYoungGen: 76640K->80K(152960K)] 1687086K->1610526K(1975680K), 0.5572511 secs]

1012.640: [GC [PSYoungGen: 76624K->96K(152960K)] 1687070K->1610542K(1975680K), 0.5618508 secs]

1178.412: [GC [PSYoungGen: 76640K->96K(152960K)] 1687086K->1610542K(1975680K), 0.5594587 secs]

1343.428: [GC [PSYoungGen: 76640K->96K(152960K)] 1687086K->1610542K(1975680K), 0.5620062 secs]

Note the FULL GC that takes about 30 seconds

Any advice would be really welcome!!!!

driving_me_nutsa at 2007-7-9 5:06:16 > top of Java-index,Java HotSpot Virtual Machine,Specifications...
# 6

Interesting that when I set NewRatio=10 instead of 8 I do not get any FULL GC when using -XX:+UseParallelGC. I think my old generation is big enough to hold all my live data and my young generation is small enough to force my large live objects to be promoted directly to the old generation, yet the young generation is still big enough to not have too many frequent minor collections. What do you think? It seems a tricky balancing act.

java -server -verbosegc -XX:+PrintCommandLineFlags -XX:+UseParallelGC -XX:+PrintTenuringDistribution -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xms2000M -Xmx2000M -XX:NewRatio=10

43.496: [GC [PSYoungGen: 164863K->23547K(86400K)] 515244K->508594K(1950080K), 0.8136308 secs]

44.438: [GC [PSYoungGen: 86395K->62774K(125632K)] 571442K->570703K(1989312K), 1.4772611 secs]

46.034: [GC [PSYoungGen: 125599K->62773K(125632K)] 633528K->633094K(1989312K), 1.2770536 secs]

47.356: [GC [PSYoungGen: 125621K->62769K(125632K)] 695942K->695705K(1989312K), 1.1899351 secs]

48.596: [GC [PSYoungGen: 125594K->62768K(125632K)] 758530K->758429K(1989312K), 0.6875967 secs]

49.338: [GC [PSYoungGen: 125579K->61852K(125632K)] 821241K->820261K(1989312K), 0.5402346 secs]

49.944: [GC [PSYoungGen: 124669K->62647K(125632K)] 883078K->882692K(1989312K), 0.5347069 secs]

50.536: [GC [PSYoungGen: 125481K->62765K(125632K)] 945526K->945337K(1989312K), 0.5211941 secs]

51.106: [GC [PSYoungGen: 125584K->62749K(125632K)] 1008156K->1008043K(1989312K), 0.5356979 secs]

51.698: [GC [PSYoungGen: 125586K->62765K(125632K)] 1070880K->1070859K(1989312K), 0.5566308 secs]

52.314: [GC [PSYoungGen: 125590K->62765K(125632K)] 1133685K->1133620K(1989312K), 0.5370862 secs]

52.906: [GC [PSYoungGen: 125587K->62765K(125632K)] 1196443K->1196421K(1989312K), 0.5360398 secs]

53.496: [GC [PSYoungGen: 125606K->62757K(125632K)] 1259262K->1259249K(1989312K), 0.5577733 secs]

54.108: [GC [PSYoungGen: 125599K->62765K(125632K)] 1322090K->1322018K(1989312K), 0.5419387 secs]

54.714: [GC [PSYoungGen: 125606K->62765K(125632K)] 1384859K->1384818K(1989312K), 0.5350697 secs]

55.306: [GC [PSYoungGen: 125610K->62781K(125632K)] 1447664K->1447638K(1989312K), 0.5538891 secs]

55.901: [GC [PSYoungGen: 125619K->62781K(125632K)] 1510477K->1510408K(1989312K), 0.5003064 secs]

56.448: [GC [PSYoungGen: 125615K->62782K(125632K)] 1573242K->1573308K(1989312K), 0.4973860 secs]

56.994: [GC [PSYoungGen: 125603K->62779K(125632K)] 1636129K->1636000K(1989312K), 0.5245888 secs]

57.576: [GC [PSYoungGen: 125612K->62773K(125632K)] 1698834K->1698921K(1989312K), 0.5033827 secs]

193.856: [GC [PSYoungGen: 125621K->332K(125632K)] 1761769K->1699077K(1989312K),0.6723061 secs]

330.986: [GC [PSYoungGen: 63180K->144K(125632K)] 1761925K->1699133K(1989312K), 0.6990433 secs]

468.296: [GC [PSYoungGen: 62992K->160K(125632K)] 1761981K->1699149K(1989312K), 0.6957411 secs]

605.816: [GC [PSYoungGen: 63008K->176K(125632K)] 1761997K->1699165K(1989312K), 0.7022184 secs]

742.216: [GC [PSYoungGen: 63024K->160K(125632K)] 1762013K->1699149K(1989312K), 0.6994954 secs]

878.946: [GC [PSYoungGen: 63008K->160K(125632K)] 1761997K->1699149K(1989312K), 0.7020897 secs]

1016.296: [GC [PSYoungGen: 63008K->160K(125632K)] 1761997K->1699149K(1989312K), 0.7015459 secs]

1153.096: [GC [PSYoungGen: 63008K->160K(125632K)] 1761997K->1699149K(1989312K), 0.7017852 secs]

1289.186: [GC [PSYoungGen: 63008K->160K(125632K)] 1761997K->1699149K(1989312K), 0.7085584 secs]

1425.296: [GC [PSYoungGen: 63008K->160K(125632K)] 1761997K->1699149K(1989312K), 0.7002911 secs]

1561.496: [GC [PSYoungGen: 63008K->160K(125632K)] 1761997K->1699149K(1989312K),0.7022239 secs]

1698.166: [GC [PSYoungGen: 63008K->160K(125632K)] 1761997K->1699149K(1989312K),0.7018851 secs]

1834.946: [GC [PSYoungGen: 63008K->160K(125632K)] 1761997K->1699149K(1989312K),0.6986453 secs]

1972.036: [GC [PSYoungGen: 63008K->160K(125632K)] 1761997K->1699149K(1989312K),0.6986128 secs]

driving_me_nutsa at 2007-7-9 5:06:16 > top of Java-index,Java HotSpot Virtual Machine,Specifications...
Java HotSpot Virtual Machine
Specifications

Java HotSpot Virtual Machine New Topic

Java HotSpot Virtual Machine Hot Topic

Java HotSpot Virtual Machine

All Classified