January 2008 - hotspot-gc-dev

Re: Perplexing GC Time Growth
by Y.S.Ramakrishna＠Sun.COM 13 May '08

13 May '08

Jason Vasquez wrote: > I've enabled the flag and am starting the test now. It takes a few > hours before we can see definite trending, but I'll let you know what > we see. > > And yes, we do a fair bit of classloading/reflection work in the > application. On the hunch that it was the accumulation of classes in the perm gen and the system dictionary that was the root cause of the troubles here (which the explicit class unloading will now hopefully take care of -- recall that cms does not by default unload classes to keep cms remark pause times low), you might want to monitor the size of the perm gen (with and without the CMSClassUnloadingEnabled option) by means of "jstat -gc ..." (which will show perm gen utilization under the "PU" column). This (lack of class unloading w/CMS unless explicitly requested) will hopefully be much less of an issue going forward as a result of work currently being done towards 6543076 (some of which occurred under 6634032 recently discussed on this list); until that time you might find the feature in 6541037 (available as of 6u4 in a production JVM) useful. I look forward to the results of yr test; thanks! -- ramki > > Thanks, > jason > > > On Jan 2, 2008, at 17:02 , Y.S.Ramakrishna(a)Sun.COM wrote: > >> Very cool log, showing a near linear and monotonic growth >> not only in scavenge times, but also in initial mark and >> remark times, see attached plots produced by the gc histogram >> tool (from Tony Printezis, John Coomes et al). Then, looking >> also at the log file, one also sees that the live data following >> a GC is also increasing monotonically. >> >> While we think of potential reasons for this, or mull over >> appropriate sensors that can lay bare the root cause here, >> could you, on a quick hunch, do a quick experiment and tell >> me if adding the options -XX:+CMSClassUnloadingEnabled makes >> any difference to the observations above. [Does your application >> do lots of class loading or reflection or string interning?] >> >> thanks. >> -- ramki >> >> Jason Vasquez wrote: >>> I've attached a representative garbage log. To my eye, I don't >>> see anything specific that seems to indicate an event, but >>> hopefully more experienced eyes will see something different :) >>> Thanks, >>> -jason >>> On Jan 1, 2008, at 15:46 , Y Srinivas Ramakrishna wrote: >>>> It's probably a combination of card-scanning times and allocation >>>> slow-down >>>> (but probably more of the former). >>>> >>>> We've had some internal instrumentation of card-scanning times in >>>> the JVM which >>>> unfortunately has not made into the JVM code proper because the >>>> instrumentation >>>> is not as lightweight as to be enabled in production. Perhaps a >>>> spin on a test system >>>> with the card-scanning times explicitly called out might shed light. >>>> >>>> Basically what happens with CMS is that allocation is from free >>>> lists, and lacking >>>> something like big bag of pages (BBOP) allocation, this has >>>> traditionally tended to >>>> scatter the allocated objects over a large number of pages. This >>>> increases card-scanning >>>> times, although one would normally expect that this would eventually >>>> stabilize. >>>> >>>> Do the scavenge times increase suddenly after a specific event or >>>> do they just >>>> creep up slowly after each scavenge? The complete GC log would be >>>> useful to >>>> look at to answer that question. >>>> >>>> -- ramki >>>> >>>> >>>> ----- Original Message ----- >>>> From: Jason Vasquez <jason(a)mugfu.com> >>>> Date: Monday, December 31, 2007 10:21 am >>>> Subject: Perplexing GC Time Growth >>>> To: hotspot-gc-use(a)openjdk.java.net >>>> >>>> >>>>> Hi all, >>>>> >>>>> I'm having a perplexing problem -- the garbage collector appears >>>>> to be >>>>> >>>>> functioning well, with a nice object/garbage lifecycle, yet minor >>>>> GC >>>>> >>>>> times increase over the life of the process inexplicably. We are >>>>> working with telephony hardware with this application, so keeping >>>>> GC >>>>> >>>>> pauses very low is quite important. (keeping well below 100 ms >>>>> would >>>>> >>>>> be ideal) >>>>> >>>>> Here is the current configuration we are using: >>>>> >>>>> -server \ >>>>> -Xloggc:garbage.log \ >>>>> -XX:+PrintGCDetails \ >>>>> -Dsun.rmi.dgc.server.gcInterval=3600000 \ >>>>> -Dsun.rmi.dgc.client.gcInterval=3600000 \ >>>>> -XX:ParallelGCThreads=8 \ >>>>> -XX:+UseParNewGC \ >>>>> -XX:+UseConcMarkSweepGC \ >>>>> -XX:+PrintGCTimeStamps \ >>>>> -XX:-TraceClassUnloading \ >>>>> -XX:+AggressiveOpts \ >>>>> -Xmx512M \ >>>>> -Xms512M \ >>>>> -Xmn128M \ >>>>> -XX:MaxTenuringThreshold=6 \ >>>>> -XX:+ExplicitGCInvokesConcurrent >>>>> >>>>> A large number of our bigger objects size-wise live for >>>>> approximately >>>>> >>>>> 4-5 minutes, thus the larger young generation, and tenuring >>>>> threshold. >>>>> >>>>> This seems to be successful in filtering most objects before they >>>>> reach the tenured gen. (8 core x86 server, running 1.6.0_03-b05 >>>>> on 32- >>>>> >>>>> bit Linux, kernel rev 2.6.18) >>>>> >>>>> Here is a representative snippet of our garbage log: >>>>> >>>>> 487.135: [GC 487.135: [ParNew: 112726K->7290K(118016K), 0.0218110 >>>>> secs] 134494K->29058K(511232K), 0.0220520 secs] >>>>> 557.294: [GC 557.294: [ParNew: 112250K->7976K(118016K), 0.0204220 >>>>> secs] 134018K->29744K(511232K), 0.0206690 secs] >>>>> 607.025: [GC 607.025: [ParNew: 112936K->7831K(118016K), 0.0231230 >>>>> secs] 134704K->30003K(511232K), 0.0233670 secs] >>>>> 672.522: [GC 672.522: [ParNew: 112791K->7361K(118016K), 0.0253620 >>>>> secs] 134963K->29533K(511232K), 0.0256080 secs] >>>>> ... >>>>> 4006.635: [GC 4006.635: [ParNew: 112983K->7386K(118016K), 0.0385960 >>>>> secs] 141969K->36608K(511232K), 0.0388460 secs] >>>>> 4083.066: [GC 4083.066: [ParNew: 112346K->8439K(118016K), 0.0365940 >>>>> secs] 141568K->37661K(511232K), 0.0368340 secs] >>>>> 4158.457: [GC 4158.457: [ParNew: 113399K->7152K(118016K), 0.0360540 >>>>> secs] 142621K->36374K(511232K), 0.0362990 secs] >>>>> 4228.312: [GC 4228.313: [ParNew: 112112K->8738K(118016K), 0.0362510 >>>>> secs] 141334K->38083K(511232K), 0.0365050 secs] >>>>> 4293.800: [GC 4293.800: [ParNew: 113698K->8294K(118016K), 0.0368700 >>>>> secs] 143043K->37917K(511232K), 0.0371160 secs] >>>>> ... >>>>> 10489.555: [GC 10489.556: [ParNew: 112701K->7770K(118016K), >>>>> 0.0639770 >>>>> >>>>> secs] 151966K->47156K(511232K), 0.0642210 secs] >>>>> 10562.544: [GC 10562.544: [ParNew: 112730K->9267K(118016K), >>>>> 0.0625900 >>>>> >>>>> secs] 152116K->48772K(511232K), 0.0628470 secs] >>>>> 10622.558: [GC 10622.558: [ParNew: 114227K->8361K(118016K), >>>>> 0.0675730 >>>>> >>>>> secs] 153732K->48381K(511232K), 0.0678220 secs] >>>>> 10678.842: [GC 10678.842: [ParNew: 113056K->7214K(118016K), >>>>> 0.0669330 >>>>> >>>>> secs] 153076K->47234K(511232K), 0.0671800 secs] >>>>> ... >>>>> 177939.062: [GC 177939.062: [ParNew: 112608K->8620K(118016K), >>>>> 0.7681440 secs] 466132K->362144K(511232K), 0.7684030 secs] >>>>> 178005.483: [GC 178005.483: [ParNew: 113449K->7731K(118016K), >>>>> 0.7677300 secs] 466973K->361893K(511232K), 0.7679890 secs] >>>>> 178069.658: [GC 178069.658: [ParNew: 112670K->6814K(118016K), >>>>> 0.7700020 secs] 466832K->360976K(511232K), 0.7702590 secs] >>>>> 178133.513: [GC 178133.513: [ParNew: 111717K->7920K(118016K), >>>>> 0.7702920 secs] 465879K->362082K(511232K), 0.7705560 secs] >>>>> >>>>> As you can see, the gc times continue to increase over time, on the >>>>> order of about 10-20ms per hour. CMS runs are spaced very far >>>>> apart, >>>>> >>>>> in fact, since most objects die before reaching the tenured >>>>> generation, the CMS is triggered more by RMI DGC runs then by heap >>>>> growth. (We were getting serial GCs, apparently due to RMI DGC >>>>> before adding -XX:+ExplicitGCInvokesConcurrent) >>>>> >>>>> Here's some representative output from `jstat -gcutil -t -h10 >>>>> <pid> 2s`: >>>>> >>>>> Timestamp S0 S1 E O P YGC YGCT FGC FGCT GCT >>>>> 11067.6 55.74 0.00 89.32 9.73 59.84 168 7.471 8 0.280 7.751 >>>>> 11069.6 55.74 0.00 93.65 9.73 59.84 168 7.471 8 0.280 7.751 >>>>> 11071.6 55.74 0.00 99.34 9.73 59.84 168 7.471 8 0.280 7.751 >>>>> 11073.5 0.00 62.22 2.89 9.76 59.84 169 7.537 8 0.280 7.816 >>>>> 11075.6 0.00 62.22 4.80 9.76 59.84 169 7.537 8 0.280 7.816 >>>>> >>>>> Survivor spaces continue to sit at about 50-65% occupancy, which >>>>> seems >>>>> >>>>> fairly good to my eye. Eden fills approximately every 70 seconds, >>>>> triggering minor GCs. >>>>> >>>>> >>>>> Any ideas? This is becoming quite frustrating for us -- our >>>>> application uptime is pretty horrible with the too-frequent >>>>> scheduled >>>>> >>>>> restarts we are being forced to run. >>>>> >>>>> Thanks for any assistance you might be able to offer, >>>>> -Jason Vasquez >>>>> _______________________________________________ >>>>> hotspot-gc-use mailing list >>>>> hotspot-gc-use(a)openjdk.java.net >>>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use >> <scavenge.png><cms.png> > > _______________________________________________ > hotspot-gc-use mailing list > hotspot-gc-use(a)openjdk.java.net > http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use _______________________________________________ hotspot-gc-use mailing list hotspot-gc-use(a)openjdk.java.net http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

10 20

RuntimePermission for explicit GC
by Raman Gupta 21 Jan '08

21 Jan '08

The new -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses flag in JDK 1.6.0_04 reminds me of some behaviour that I'd like to see in future java versions. This flag is useful for an application to schedule GCs during off-hours, but what if my application imports libraries that internally have calls to System.gc()? Thankfully, this is becoming rarer, but it would be nice if System.gc() internally checked a new RuntimePermission "executeExplicitGc", and simply returned without taking any action if that permission was not granted to the calling code. If this was implemented, perhaps the signature could be changed to return a boolean if the collection was successfully scheduled? Cheers, Raman Gupta

5 6

RE: Strange isssue about OOM
by steve.zhuang＠oocl.com 16 Jan '08

16 Jan '08

Hi Ramki, Thanks for your explanation about "HandlePromotionFailure" option. >From the gc log, 25210.819: [GC 25210.820: [DefNew: 86804K->1788K(169600K), 0.0486894 secs]25210.868: [Tenured: 266146K->241318K(349568K), 1.2399896 secs] 339295K->241318K(519168K), 1.2888920 secs] 25212.108: [Full GC 25212.109: [Tenured[Unloading class sun.reflect.GeneratedConstructorAccessor314] [Unloading class sun.reflect.GeneratedMethodAccessor759] [Unloading class sun.reflect.GeneratedConstructorAccessor315] [Unloading class sun.reflect.GeneratedConstructorAccessor268] [Unloading class sun.reflect.GeneratedConstructorAccessor269] [Unloading class sun.reflect.GeneratedConstructorAccessor316] [Unloading class sun.reflect.GeneratedConstructorAccessor313] : 241318K->226997K(349568K), 1.5769614 secs] 241318K->226997K(519168K), [Perm : 27510K->27498K(65536K)], 1.5771121 secs] I still have below issues: 1. Why do a partially scavenge while Young generation still has lot of free memory? Your guess is that the application may be requesting the allocation of a large object, but I think it is impossible for our application to have such a large obejct (about 169 - 86 = 83 M). Is there any known issue about this kind of unusual gc? And is the ratio setting between Young generation and Tenured generation possible to improve it? Our current ratio is as default 1:2 (Young : Tenured) 2. We could see that some unloading classes occur in the next full gc, and seems JVM has some CR on this, is it possible related to this OOM? or if it is related to application issue, how could we avoid it? 3. We have studied JVM doc on http://java.sun.com/docs/hotspot/gc5.0/gc_tuning_5.html See: 5.2.3 Out-of-Memory Exceptions The throughput collector will throw an out-of-memory exception if too much time is being spent doing garbage collection. For example, if the JVM is spending more than 98% of the total time doing garbage collection and is recovering less than 2% of the heap, it will throw an out-of-memory expection. The implementation of this feature has changed in 1.5. The policy is the same but there may be slight differences in behavior due to the new implementation. And our gc log: 25213.699: [GC 25213.699: [DefNew: 756K->82K(169600K), 0.0078670 secs]25213.707: [Tenured[Unloading class sun.reflect.GeneratedConstructorAccessor274] : 226997K->221430K(349568K), 2.0173917 secs] 227753K->221430K(519168K), 2.0254397 secs] 25215.724: [Full GC 25215.724: [Tenured: 221430K->221422K(349568K), 1.2257687 secs] 221430K->221422K(519168K), [Perm : 27496K->27496K(65536K)], 1.2259138 secs] Seems our gc log reveals a behavior like "if the JVM is spending more than 98% of the total time doing garbage collection and is recovering less than 2% of the heap", is this the time server threw the OOM? Thanks. Best wishes, Steve Zhuang -----Original Message----- From: Y Srinivas Ramakrishna [mailto:Y.S.Ramakrishna@Sun.COM] Sent: Wednesday, January 16, 2008 3:51 AM To: CHRIS GUAN (ISDC-ISD-OOCLL/SHA) Subject: Re: RE: Strange isssue about OOM I forgot to send a pointer to the CR:- http://bugs.sun.com/view_bug.do?bug_id=6206427 There really is not all that much to see in the bug report though except that newer jvm's do this by default so you do not have to explicitly enable the feature. -- ramki ----- Original Message ----- From: Y Srinivas Ramakrishna <Y.S.Ramakrishna(a)Sun.COM> Date: Tuesday, January 15, 2008 11:22 am Subject: Re: RE: Strange isssue about OOM To: chris.guan(a)oocl.com Cc: hotspot-gc-use(a)openjdk.java.net > Hi Chris -- > > > Thanks for your help. > > > > Java version "1.4.2_13"; > > Oracle Application Server Containers for J2EE 10g (10.1.2.2.0) ; No > > System.gc(); WebService; > > > > Would you please explain "HandlePromotionFailure"?Where to see CR > > 6206427. > > > > In older versions of the JVM (such as the one you are using), we > didn't have a mechanism to recover from a partial scavenge if the > scavenge could not be completed because of lack of sufficient space in > the old generation to promote tenured objects into. So we used to be > very conservative in starting a scavenge and probably conservative in > precipitating a full collection if we felt the next scavenge would not > succeed. This conservatism could cause us to waste free space in the > old generation. See for example:- > > http://java.sun.com/docs/hotspot/gc1.4.2/#4.4.2.%20Young%20Generation% > 20Guarantee|outline > > In later JVM's, we added the ability to recover from a partially > completed scavenge and to compact the entire heap. This allowed us to > be less pessimistic about going into a scavenge, and would waste less > space in the old generation even when you run with large young > generations. See:- > > http://java.sun.com/docs/hotspot/gc5.0/gc_tuning_5.html#0.0.0.0.%20You > ng%20Generation%20Guarantee%7Coutline > > I'd actually recommend upgrading to a more recent JVM where you'd see > performance improvements, but if that is not possible, then with > 1.4.2_13, you should use -XX:+HandlePromotionFailure which should > allow you to make more efficient use of the heap by avoiding the issue > described above. > > As to the question of why you need to do, for example, the following > scavenge :- > > > > 25313.039: [GC 25313.039: [DefNew: 2421K->91K(169600K), 0.0079322 > > > secs]25313.047: [Tenured: 220264K->220182K(349568K), 1.3464051 > > > secs] > > My only guess is that the application may be requesting the allocation > of a large object. But that's a guess. (Yes, we should ideally have > that information be available from the gc logs.) > > -- ramki > > _______________________________________________ > hotspot-gc-use mailing list > hotspot-gc-use(a)openjdk.java.net > http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use IMPORTANT NOTICE Email from OOCL is confidential and may be legally privileged. If it is not intended for you, please delete it immediately unread. The internet cannot guarantee that this communication is free of viruses, interception or interference and anyone who communicates with us by email is taken to accept the risks in doing so. Without limitation, OOCL and its affiliates accept no liability whatsoever and howsoever arising in connection with the use of this email. Under no circumstances shall this email constitute a binding agreement to carry or for provision of carriage services by OOCL, which is subject to the availability of carrier's equipment and vessels and the terms and conditions of OOCL's standard bill of lading which is also available at http://www.oocl.com. _______________________________________________ hotspot-gc-use mailing list hotspot-gc-use(a)openjdk.java.net http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

2 1

Re: RE: Strange isssue about OOM
by Y Srinivas Ramakrishna 16 Jan '08

16 Jan '08

Hi Chris -- > Thanks for your help. > > Java version "1.4.2_13"; > Oracle Application Server Containers for J2EE 10g (10.1.2.2.0) ; > No System.gc(); > WebService; > > Would you please explain "HandlePromotionFailure"?Where to see CR > 6206427. > In older versions of the JVM (such as the one you are using), we didn't have a mechanism to recover from a partial scavenge if the scavenge could not be completed because of lack of sufficient space in the old generation to promote tenured objects into. So we used to be very conservative in starting a scavenge and probably conservative in precipitating a full collection if we felt the next scavenge would not succeed. This conservatism could cause us to waste free space in the old generation. See for example:- http://java.sun.com/docs/hotspot/gc1.4.2/#4.4.2.%20Young%20Generation%20Gua… In later JVM's, we added the ability to recover from a partially completed scavenge and to compact the entire heap. This allowed us to be less pessimistic about going into a scavenge, and would waste less space in the old generation even when you run with large young generations. See:- http://java.sun.com/docs/hotspot/gc5.0/gc_tuning_5.html#0.0.0.0.%20Young%20… I'd actually recommend upgrading to a more recent JVM where you'd see performance improvements, but if that is not possible, then with 1.4.2_13, you should use -XX:+HandlePromotionFailure which should allow you to make more efficient use of the heap by avoiding the issue described above. As to the question of why you need to do, for example, the following scavenge :- > > 25313.039: [GC 25313.039: [DefNew: 2421K->91K(169600K), 0.0079322 > > secs]25313.047: [Tenured: 220264K->220182K(349568K), 1.3464051 secs] My only guess is that the application may be requesting the allocation of a large object. But that's a guess. (Yes, we should ideally have that information be available from the gc logs.) -- ramki _______________________________________________ hotspot-gc-use mailing list hotspot-gc-use(a)openjdk.java.net http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

2 1

Rapid fluctuation of tenuring threshold
by James Nichols 15 Jan '08

15 Jan '08

Hello, My application has a fairly high streaming dataflow that creates a lot of short-lived objects. I've made the young generation fairly large and have a pretty big survivor space, but I still have a # of objects that end up in the old generation. As a result of this, my old generation size ramps up slowly over time until these objects are dead, then they all get cleaned up and there is a big drop in old generation usage, from about 2.5GBs to about 1GB. Most of the time it takes about 80 minutes to get up to 2.5GBs, but occasionally it happens much more rapidly, as fast at every 8 minutes. My workload does fluctuate over time, but not enough to explain this change in garbage collection behavior. I'm seeing some very odd behavior in the JVM's tuning of the tenuring threshold. Attached is a chart that plots the old generation over time (the blue line with a moving average in yellow). Each dot is a garbage collection (usually the young generation). On this chart, I also plotted the tenuring threshold in red, with a moving average in black. Each dot represents what the threshold was for that particular garbage collection. You can see around time 11,500 minutes the peaks/valleys become much more frequent as more data is ending up int the old generation. During this time, the moving average of the tenuring threshold drops substantially. This also happens during other periods where the old generation is filled up quickly. I'm not sure if this is a cause or an effect. I leaning towards the tenuring threshold being the cause because the objects ending up in the old generation are typically reclaimed in a very short period of time. I've analyzed the distribution of the tenuring threshold over a substantial period of time in my application. It appears that 25% of the time the tenuring threshold is 1, 60% of the time it's 16, and the other 15% is distributed somewhere in the middle. I'm a bit puzzled why the threshold would so rapidly change between 1 and 16, and wonder if I'm getting hosed by the auto-tuning of this threshold. Looking at the log, it rapidly goes from 1 to 16, very rarely stopping intermediately. Is it reasonable to think that something is wrong with the auto tuning to make it stay at 1 and cause the behavior I noted above? I'm running jdk 1.5.0_12 on RedHat linux and my application server is JBoss 4.0.5. My GC settings are below... I can send the gc.dat log if you want it, it's pretty big so I won't email it to the list. I've signed up to the mailing list, but please CC me on any replies. Thanks, James -server -Xms5170m -Xmx5170m -XX:NewSize=1536M -XX:MaxNewSize=1536M -XX:PermSize=512M -XX:MaxPermSize=512M -XX:MaxTenuringThreshold=30 -XX:SurvivorRatio=10 -XX:+ScavengeBeforeFullGC -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:ParallelGCThreads=3 -XX:+CMSParallelRemarkEnabled -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled -XX:+DisableExplicitGC -XX:+PrintTenuringDistribution -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -Xloggc:gc.dat _______________________________________________ hotspot-gc-use mailing list hotspot-gc-use(a)openjdk.java.net http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

2 3

Strange isssue about OOM
by chris.guan＠oocl.com 15 Jan '08

15 Jan '08

Dear, Encounter one issue about out of memory, server continued trigger gc and full gc while the memory is less used, eapesicially the [young]. Please help.Also, what is the theary to trigger gc?Many thanks. Not calling System.gc(). Performing 10 VU's test. Not reproduced. The server parameter: -server -Xms512M -Xmx512M -verbose:gc -XX:PermSize=64M -XX:MaxPermSize=64M. The log: 25185.728: [GC 25185.728: [DefNew: 163242K->163242K(169600K), 0.0000587 secs]25185.728: [Tenured: 234502K->252491K(349568K), 1.3021262 secs] 397745K->252491K(519168K), 1.3029282 secs] Total time for which application threads were stopped: 1.3040612 seconds Application time: 23.7854558 seconds 25210.819: [GC 25210.820: [DefNew: 86804K->1788K(169600K), 0.0486894 secs]25210.868: [Tenured: 266146K->241318K(349568K), 1.2399896 secs] 339295K->241318K(519168K), 1.2888920 secs] 25212.108: [Full GC 25212.109: [Tenured[Unloading class sun.reflect.GeneratedConstructorAccessor314] [Unloading class sun.reflect.GeneratedMethodAccessor759] [Unloading class sun.reflect.GeneratedConstructorAccessor315] [Unloading class sun.reflect.GeneratedConstructorAccessor268] [Unloading class sun.reflect.GeneratedConstructorAccessor269] [Unloading class sun.reflect.GeneratedConstructorAccessor316] [Unloading class sun.reflect.GeneratedConstructorAccessor313] : 241318K->226997K(349568K), 1.5769614 secs] 241318K->226997K(519168K), [Perm : 27510K->27498K(65536K)], 1.5771121 secs] Total time for which application threads were stopped: 2.8672106 seconds Application time: 0.0086622 seconds 25213.699: [GC 25213.699: [DefNew: 756K->82K(169600K), 0.0078670 secs]25213.707: [Tenured[Unloading class sun.reflect.GeneratedConstructorAccessor274] : 226997K->221430K(349568K), 2.0173917 secs] 227753K->221430K(519168K), 2.0254397 secs] 25215.724: [Full GC 25215.724: [Tenured: 221430K->221422K(349568K), 1.2257687 secs] 221430K->221422K(519168K), [Perm : 27496K->27496K(65536K)], 1.2259138 secs] Total time for which application threads were stopped: 3.2556802 seconds Application time: 21.5991046 seconds 25238.563: [GC 25238.563: [DefNew: 18728K->296K(169600K), 0.0169044 secs]25238.580: [Tenured: 221422K->221605K(349568K), 1.3133015 secs] 240150K->221605K(519168K), 1.3303972 secs] 25239.893: [Full GC 25239.894: [Tenured: 221605K->220330K(349568K), 1.2038988 secs] 221605K->220330K(519168K), [Perm : 27497K->27497K(65536K)], 1.2040751 secs] Total time for which application threads were stopped: 2.5488005 seconds Application time: 0.0188518 seconds 25241.130: [GC 25241.130: [DefNew: 1990K->59K(169600K), 0.0071533 secs]25241.137: [Tenured: 220330K->220344K(349568K), 1.2219109 secs] 222321K->220344K(519168K), 1.2292561 secs] 25242.359: [Full GC 25242.359: [Tenured: 220344K->220335K(349568K), 1.2026312 secs] 220344K->220335K(519168K), [Perm : 27497K->27497K(65536K)], 1.2027791 secs] Total time for which application threads were stopped: 2.4439904 seconds Application time: 24.2665427 seconds 25267.833: [GC 25267.833: [DefNew: 24971K->255K(169600K), 0.0081354 secs]25267.841: [Tenured: 220335K->220542K(349568K), 1.2416907 secs] 245306K->220542K(519168K), 1.2500197 secs] 25269.083: [Full GC 25269.083: [Tenured: 220542K->220317K(349568K), 1.2465385 secs] 220542K->220317K(519168K), [Perm : 27497K->27497K(65536K)], 1.2466957 secs] Total time for which application threads were stopped: 2.5006234 seconds Application time: 9.1710434 seconds 25279.513: [GC 25279.513: [DefNew: 11184K->124K(169600K), 0.0191095 secs]25279.532: [Tenured: 220317K->220247K(349568K), 1.2142263 secs] 231502K->220247K(519168K), 1.2335457 secs] 25280.746: [Full GC 25280.746: [Tenured: 220247K->220237K(349568K), 1.2042132 secs] 220247K->220237K(519168K), [Perm : 27497K->27497K(65536K)], 1.2043556 secs] Total time for which application threads were stopped: 2.4500521 seconds Application time: 28.5731236 seconds 25310.536: [GC 25310.536: [DefNew: 20905K->185K(169600K), 0.0174417 secs]25310.554: [Tenured: 220237K->220422K(349568K), 1.2108142 secs] 241142K->220422K(519168K), 1.2284657 secs] 25311.765: [Full GC 25311.765: [Tenured: 220422K->220264K(349568K), 1.2223217 secs] 220422K->220264K(519168K), [Perm : 27497K->27497K(65536K)], 1.2224701 secs] Total time for which application threads were stopped: 2.4631855 seconds Application time: 0.0368244 seconds 25313.039: [GC 25313.039: [DefNew: 2421K->91K(169600K), 0.0079322 secs]25313.047: [Tenured: 220264K->220182K(349568K), 1.3464051 secs] 222685K->220182K(519168K), 1.3545552 secs] 25314.393: [Full GC 25314.394: [Tenured: 220182K->220172K(349568K), 1.2893013 secs] 220182K->220172K(519168K), [Perm : 27497K->27497K(65536K)], 1.2894685 secs] Total time for which application threads were stopped: 2.6585330 seconds Application time: 45.1138619 seconds 25360.803: [GC 25360.803: [DefNew: 29023K->222K(169600K), 0.0078027 secs]25360.811: [Tenured: 220172K->220388K(349568K), 1.2135921 secs] 249195K->220388K(519168K), 1.2215896 secs] 25362.025: [Full GC 25362.025: [Tenured: 220388K->220294K(349568K), 1.1972240 secs] 220388K->220294K(519168K), [Perm : 27497K->27497K(65536K)], 1.1973704 secs] Total time for which application threads were stopped: 2.4229267 seconds Application time: 31.0328978 seconds 25394.270: [GC 25394.270: [DefNew: 19657K->162K(169600K), 0.0088962 secs]25394.279: [Tenured: 220294K->220251K(349568K), 1.3206682 secs] 239951K->220251K(519168K), 1.3297797 secs] 25395.599: [Full GC 25395.600: [Tenured: 220251K->220241K(349568K), 1.1989645 secs] 220251K->220241K(519168K), [Perm : 27497K->27497K(65536K)], 1.1991104 secs] Total time for which application threads were stopped: 2.5428534 seconds Application time: 92.3087423 seconds 25489.129: [GC 25489.130: [DefNew: 54368K->315K(169600K), 0.0116064 secs]25489.141: [Tenured: 220241K->220556K(349568K), 1.5860020 secs] 274610K->220556K(519168K), 1.5978559 secs] 25490.727: [Full GC 25490.728: [Tenured: 220556K->220393K(349568K), 1.7381398 secs] 220556K->220393K(519168K), [Perm : 27497K->27497K(65536K)], 1.7382875 secs] Total time for which application threads were stopped: 3.3583027 seconds Application time: 5.9312480 seconds 25498.413: [GC 25498.413: [DefNew: 5241K->93K(169600K), 0.0172377 secs]25498.430: [Tenured: 220393K->220184K(349568K), 1.2922102 secs] 225635K->220184K(519168K), 1.3096568 secs] 25499.722: [Full GC 25499.722: [Tenured: 220184K->220175K(349568K), 1.1997437 secs] 220184K->220175K(519168K), [Perm : 27497K->27497K(65536K)], 1.1999031 secs] Total time for which application threads were stopped: 2.5211851 seconds Application time: 30.6028562 seconds 25531.528: [GC 25531.528: [DefNew: 17776K->156K(169600K), 0.0171998 secs]25531.545: [Tenured: 220175K->220330K(349568K), 1.2259878 secs] 237951K->220330K(519168K), 1.2433891 secs] 25532.771: [Full GC 25532.771: [Tenured: 220330K->220239K(349568K), 1.6592153 secs] 220330K->220239K(519168K), [Perm : 27499K->27498K(65536K)], 1.6593672 secs] Total time for which application threads were stopped: 2.9038367 seconds Application time: 60.4048509 seconds 25594.836: [GC 25594.837: [DefNew: 33874K->231K(169600K), 0.0168536 secs]25594.853: [Tenured: 220239K->220323K(349568K), 1.2180811 secs] 254113K->220323K(519168K), 1.2351280 secs] 25596.072: [Full GC 25596.072: [Tenured: 220323K->220313K(349568K), 1.2081214 secs] 220323K->220313K(519168K), [Perm : 27498K->27498K(65536K)], 1.2082667 secs] Total time for which application threads were stopped: 2.4445252 seconds Application time: 197.3583592 seconds 25794.639: [GC 25794.640: [DefNew: 106524K->606K(169600K), 0.0115235 secs]25794.651: [Tenured: 220313K->220918K(349568K), 1.2305807 secs] 326837K->220918K(519168K), 1.2423031 secs] 25795.882: [Full GC 25795.882: [Tenured: 220918K->220684K(349568K), 1.4731407 secs] 220918K->220684K(519168K), [Perm : 27499K->27498K(65536K)], 1.4732974 secs] Total time for which application threads were stopped: 2.7168052 seconds Application time: 164.9563502 seconds 25962.313: [GC 25962.313: [DefNew: 82927K->507K(169600K), 0.0091128 secs]25962.322: [Tenured: 220684K->220600K(349568K), 1.2012755 secs] 303612K->220600K(519168K), 1.2105846 secs] 25963.523: [Full GC 25963.524: [Tenured: 220600K->220590K(349568K), 1.2976048 secs] 220600K->220590K(519168K), [Perm : 27498K->27498K(65536K)], 1.2977544 secs] Total time for which application threads were stopped: 2.5095478 seconds Application time: 318.2895362 seconds 26283.112: [GC 26283.112: [DefNew: 164480K->164480K(169600K), 0.0000494 secs]26283.112: [Tenured: 220590K->221495K(349568K), 1.3880562 secs] 385070K->221495K(519168K), 1.3883772 secs] Total time for which application threads were stopped: 1.3895031 seconds Application time: 318.6411712 seconds 26603.143: [GC 26603.143: [DefNew: 164480K->164480K(169600K), 0.0000486 secs]26603.143: [Tenured: 221495K->222391K(349568K), 1.3624147 secs] 385975K->222391K(519168K), 1.3626644 secs] Total time for which application threads were stopped: 1.3641826 seconds Application time: 318.5726610 seconds 26923.080: [GC 26923.080: [DefNew: 164480K->164480K(169600K), 0.0000489 secs]26923.080: [Tenured: 222391K->221000K(349568K), 1.3836587 secs] 386871K->221000K(519168K), 1.3839017 secs] Total time for which application threads were stopped: 1.3854997 seconds Application time: 319.1556307 seconds 27243.621: [GC 27243.621: [DefNew: 164480K->164480K(169600K), 0.0000463 secs]27243.621: [Tenured: 221000K->221899K(349568K), 1.7850120 secs] 385480K->221899K(519168K), 1.7852453 secs] Total time for which application threads were stopped: 1.7865089 seconds Application time: 318.6705844 seconds 27564.079: [GC 27564.079: [DefNew: 164480K->164480K(169600K), 0.0000428 secs]27564.079: [Tenured: 221899K->222801K(349568K), 1.5890202 secs] 386379K->222801K(519168K), 1.5892684 secs] Total time for which application threads were stopped: 1.5909515 seconds Application time: 318.5994769 seconds 27884.269: [GC 27884.269: [DefNew: 164480K->164480K(169600K), 0.0000471 secs]27884.269: [Tenured: 222801K->223693K(349568K), 1.6433190 secs] 387281K->223693K(519168K), 1.6435445 secs] Total time for which application threads were stopped: 1.6447412 seconds Application time: 94.5616049 seconds 27980.476: [GC 27980.476: [DefNew: 51783K->327K(169600K), 0.0179721 secs]27980.494: [Tenured: 223693K->220424K(349568K), 1.2211616 secs] 275476K->220424K(519168K), 1.2393261 secs] 27981.715: [Full GC 27981.715: [Tenured: 220424K->220413K(349568K), 1.2103792 secs] 220424K->220413K(519168K), [Perm : 27498K->27498K(65536K)], 1.2105386 secs] Total time for which application threads were stopped: 2.4509644 seconds Application time: 32.3719363 seconds 28015.299: [GC 28015.299: [DefNew: 18543K->164K(169600K), 0.0073310 secs]28015.306: [Tenured: 220413K->220577K(349568K), 1.2056721 secs] 238957K->220577K(519168K), 1.2131937 secs] 28016.512: [Full GC 28016.512: [Tenured: 220577K->220252K(349568K), 1.2023572 secs] 220577K->220252K(519168K), [Perm : 27499K->27498K(65536K)], 1.2025188 secs] Total time for which application threads were stopped: 2.4167372 seconds -------- 08/01/03 17:32:28 Stop process Thanks & Regards Chris Guan Tel: 24056255 IMPORTANT NOTICE Email from OOCL is confidential and may be legally privileged. If it is not intended for you, please delete it immediately unread. The internet cannot guarantee that this communication is free of viruses, interception or interference and anyone who communicates with us by email is taken to accept the risks in doing so. Without limitation, OOCL and its affiliates accept no liability whatsoever and howsoever arising in connection with the use of this email. Under no circumstances shall this email constitute a binding agreement to carry or for provision of carriage services by OOCL, which is subject to the availability of carrier's equipment and vessels and the terms and conditions of OOCL's standard bill of lading which is also available at http://www.oocl.com. _______________________________________________ hotspot-gc-use mailing list hotspot-gc-use(a)openjdk.java.net http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

3 3

Re: Perplexing GC Time Growth
by Jason Vasquez 09 Jan '08

09 Jan '08

Hi Ramki, Sorry for the delay, I'm on vacation visiting some family over a long weekend, trying not to draw the wrath of my wife for stealing time away hopping on the VPN to check things out :) Anyway, I've attached the latest garbage log, unfortunately, it doesn't seem to have changed things much (although I can see that the flags are now taking affect) -jason On Jan 4, 2008, at 14:54 , Y Srinivas Ramakrishna wrote: > Hi Jason -- did you get a chance to check what happens to scavenge > times with both the class unloading options specified as stated below. > > thanks! > -- ramki > > ----- Original Message ----- > From: Y.S.Ramakrishna(a)Sun.COM > Date: Thursday, January 3, 2008 4:10 pm > Subject: Re: Perplexing GC Time Growth > To: Jason Vasquez <jason(a)mugfu.com> > Cc: hotspot-gc-use(a)openjdk.java.net > > >> Hi Jason -- >> >> Y.S.Ramakrishna(a)Sun.COM wrote: >> ... >>> While we think of potential reasons for this, or mull over >>> appropriate sensors that can lay bare the root cause here, >>> could you, on a quick hunch, do a quick experiment and tell >>> me if adding the options -XX:+CMSClassUnloadingEnabled makes >>> any difference to the observations above. [Does your application >>> do lots of class loading or reflection or string interning?] >> >> I think i screwed up a bit here. I was assuming you were using >> the (newest) OpenJDK build. As it happens, in 6u3 and older >> you need to specify both +CMSClassUnloadingEnabled _and_ >> +CMSPermGenSweepingEnabled, else you do not get the desired effect. >> Sorry this was fixed after 6u3, so the additional flag did not >> do anything in your case. >> >> Let me know if the additional flag (please use both) made >> a difference, and apologies for the bad user interface here >> (set right as of 6u4 and in OpenJDK). >> >> -- ramki >> >>> >> _______________________________________________ hotspot-gc-use mailing list hotspot-gc-use(a)openjdk.java.net http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

3 5

Request for review (small): 6642634 Test nsk/regression/b6186200 crashed with SIGSEGV
by Y Srinivas Ramakrishna 08 Jan '08

08 Jan '08

attached.

1 0

Re: Perplexing GC Time Growth
by Y Srinivas Ramakrishna 07 Jan '08

07 Jan '08

It's probably a combination of card-scanning times and allocation slow-down (but probably more of the former). We've had some internal instrumentation of card-scanning times in the JVM which unfortunately has not made into the JVM code proper because the instrumentation is not as lightweight as to be enabled in production. Perhaps a spin on a test system with the card-scanning times explicitly called out might shed light. Basically what happens with CMS is that allocation is from free lists, and lacking something like big bag of pages (BBOP) allocation, this has traditionally tended to scatter the allocated objects over a large number of pages. This increases card-scanning times, although one would normally expect that this would eventually stabilize. Do the scavenge times increase suddenly after a specific event or do they just creep up slowly after each scavenge? The complete GC log would be useful to look at to answer that question. -- ramki ----- Original Message ----- From: Jason Vasquez <jason(a)mugfu.com> Date: Monday, December 31, 2007 10:21 am Subject: Perplexing GC Time Growth To: hotspot-gc-use(a)openjdk.java.net > Hi all, > > I'm having a perplexing problem -- the garbage collector appears to be > > functioning well, with a nice object/garbage lifecycle, yet minor GC > > times increase over the life of the process inexplicably. We are > working with telephony hardware with this application, so keeping GC > > pauses very low is quite important. (keeping well below 100 ms would > > be ideal) > > Here is the current configuration we are using: > > -server \ > -Xloggc:garbage.log \ > -XX:+PrintGCDetails \ > -Dsun.rmi.dgc.server.gcInterval=3600000 \ > -Dsun.rmi.dgc.client.gcInterval=3600000 \ > -XX:ParallelGCThreads=8 \ > -XX:+UseParNewGC \ > -XX:+UseConcMarkSweepGC \ > -XX:+PrintGCTimeStamps \ > -XX:-TraceClassUnloading \ > -XX:+AggressiveOpts \ > -Xmx512M \ > -Xms512M \ > -Xmn128M \ > -XX:MaxTenuringThreshold=6 \ > -XX:+ExplicitGCInvokesConcurrent > > A large number of our bigger objects size-wise live for approximately > > 4-5 minutes, thus the larger young generation, and tenuring threshold. > > This seems to be successful in filtering most objects before they > reach the tenured gen. (8 core x86 server, running 1.6.0_03-b05 on 32- > > bit Linux, kernel rev 2.6.18) > > Here is a representative snippet of our garbage log: > > 487.135: [GC 487.135: [ParNew: 112726K->7290K(118016K), 0.0218110 > secs] 134494K->29058K(511232K), 0.0220520 secs] > 557.294: [GC 557.294: [ParNew: 112250K->7976K(118016K), 0.0204220 > secs] 134018K->29744K(511232K), 0.0206690 secs] > 607.025: [GC 607.025: [ParNew: 112936K->7831K(118016K), 0.0231230 > secs] 134704K->30003K(511232K), 0.0233670 secs] > 672.522: [GC 672.522: [ParNew: 112791K->7361K(118016K), 0.0253620 > secs] 134963K->29533K(511232K), 0.0256080 secs] > ... > 4006.635: [GC 4006.635: [ParNew: 112983K->7386K(118016K), 0.0385960 > secs] 141969K->36608K(511232K), 0.0388460 secs] > 4083.066: [GC 4083.066: [ParNew: 112346K->8439K(118016K), 0.0365940 > secs] 141568K->37661K(511232K), 0.0368340 secs] > 4158.457: [GC 4158.457: [ParNew: 113399K->7152K(118016K), 0.0360540 > secs] 142621K->36374K(511232K), 0.0362990 secs] > 4228.312: [GC 4228.313: [ParNew: 112112K->8738K(118016K), 0.0362510 > secs] 141334K->38083K(511232K), 0.0365050 secs] > 4293.800: [GC 4293.800: [ParNew: 113698K->8294K(118016K), 0.0368700 > secs] 143043K->37917K(511232K), 0.0371160 secs] > ... > 10489.555: [GC 10489.556: [ParNew: 112701K->7770K(118016K), 0.0639770 > > secs] 151966K->47156K(511232K), 0.0642210 secs] > 10562.544: [GC 10562.544: [ParNew: 112730K->9267K(118016K), 0.0625900 > > secs] 152116K->48772K(511232K), 0.0628470 secs] > 10622.558: [GC 10622.558: [ParNew: 114227K->8361K(118016K), 0.0675730 > > secs] 153732K->48381K(511232K), 0.0678220 secs] > 10678.842: [GC 10678.842: [ParNew: 113056K->7214K(118016K), 0.0669330 > > secs] 153076K->47234K(511232K), 0.0671800 secs] > ... > 177939.062: [GC 177939.062: [ParNew: 112608K->8620K(118016K), > 0.7681440 secs] 466132K->362144K(511232K), 0.7684030 secs] > 178005.483: [GC 178005.483: [ParNew: 113449K->7731K(118016K), > 0.7677300 secs] 466973K->361893K(511232K), 0.7679890 secs] > 178069.658: [GC 178069.658: [ParNew: 112670K->6814K(118016K), > 0.7700020 secs] 466832K->360976K(511232K), 0.7702590 secs] > 178133.513: [GC 178133.513: [ParNew: 111717K->7920K(118016K), > 0.7702920 secs] 465879K->362082K(511232K), 0.7705560 secs] > > As you can see, the gc times continue to increase over time, on the > order of about 10-20ms per hour. CMS runs are spaced very far apart, > > in fact, since most objects die before reaching the tenured > generation, the CMS is triggered more by RMI DGC runs then by heap > growth. (We were getting serial GCs, apparently due to RMI DGC > before adding -XX:+ExplicitGCInvokesConcurrent) > > Here's some representative output from `jstat -gcutil -t -h10 <pid> 2s`: > > Timestamp S0 S1 E O P YGC YGCT FGC FGCT GCT > 11067.6 55.74 0.00 89.32 9.73 59.84 168 7.471 8 0.280 7.751 > 11069.6 55.74 0.00 93.65 9.73 59.84 168 7.471 8 0.280 7.751 > 11071.6 55.74 0.00 99.34 9.73 59.84 168 7.471 8 0.280 7.751 > 11073.5 0.00 62.22 2.89 9.76 59.84 169 7.537 8 0.280 7.816 > 11075.6 0.00 62.22 4.80 9.76 59.84 169 7.537 8 0.280 7.816 > > Survivor spaces continue to sit at about 50-65% occupancy, which seems > > fairly good to my eye. Eden fills approximately every 70 seconds, > triggering minor GCs. > > > Any ideas? This is becoming quite frustrating for us -- our > application uptime is pretty horrible with the too-frequent scheduled > > restarts we are being forced to run. > > Thanks for any assistance you might be able to offer, > -Jason Vasquez > _______________________________________________ > hotspot-gc-use mailing list > hotspot-gc-use(a)openjdk.java.net > http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use _______________________________________________ hotspot-gc-use mailing list hotspot-gc-use(a)openjdk.java.net http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

5 5

Perplexing GC Time Growth
by Ciciora, Paul 04 Jan '08

04 Jan '08

If you don't mind me asking, what do the times look like after a remark cycle? Also have you run with PrintTenuringDistribution? It's a nice way to make sure you have the optimal number of slots.

2 1