May 2008 - hotspot-gc-dev

Proposal: MaxTenuringThreshold and age field size changes
by Tony Printezis 05 Jun '08

05 Jun '08

Hi all, We are considering making some changes to the way the MaxTenuringThreshold parameter is handled and to the size of the age field. We'd appreciate your feedback. *Background.* The -XX:MaxTenuringThreshold=n (or MTT for short) parameter dictates how many times objects will be copied within the young generation (i.e., between the survivor spaces) before they are promoted (tenured) to the old generation. Each object has an "age" field in its header which is incremented every time an object is copied within the young generation. When the age field reaches the value of MTT, the object is promoted to the old generation (I've left out some detail here...). The parameter -XX:+NeverTenure tells the GC never to tenure objects willingly (they will be promoted only when the target survivor space is full). (out of curiosity: does anyone actually use -XX:+NeverTenure?) Originally, in the HotSpot JVM, we had 5 bits per object for the age field (for a max value of 31, so values of MTT would make sense if they were <= 31). A couple of years ago (since 5u6 IIRC), the age field "lost" one bit and it now only has 4 (for a max value of 15). *The Problem.* We have got reports from customers that, when they use a MTT > 15 in the latest JVMs (say, when they use their older settings), the tenuring policy behaves strangely and piles up objects on age 15 (i.e., objects reach age 15 and are not then promoted, but are kept at age 15). This happens because if MTT is set to a value higher than the max age (which is currently 15, as I said earlier), the policy essentially behaves the same as -XX:+NeverTenure. We have got at least two reports that this has a detrimental effect on performance since (a) objects are either retained too long in the young gen, imposing copying overhead, or (b) objects are promoted too early, since objects much older than them, and which they should have got promoted some time ago, filled up the survivor space, forcing younger objects to be promoted instead. We also got some reports from customers that the decrease in age field size has actually created performance issues for them (they get better GC behavior if they keep objects in the young gen longer, so that they can reclaim more of them in the young gen and promote less). *Change Proposal.* We are thinking of applying the following changes: - If MTT is set by the user to a value > max age, we will actually set it to max age. So, a high MTT value will not be equivalent to setting -XX:+NeverTenure (if users really want they never tenure policy, they'd get it with the -XX:+NeverTenure parameter). We believe that this is the more natural interpretation of the MTT parameter (and it will be less confusing to users with "old" settings), even though it will behave differently to the way it currently behaves. - Even though we cannot add an extra bit to the age field in the 32-bit JVM (the space in an object's mark word is at a premium in the 32-bit JVM), we think we can increase the age field size, and as a result the max value of MTT, in the 64-bit JVM (to even higher than 5 bits too). We feel this is a worthwhile change, given that 64-bit JVM users will be able to use MTT values > 15, despite the confusion that it might cause (the max MTT value will be different in the 32-bit and 64-bit JVMs; incidentally, the "compressed oops" JVM will also have the larger age fields too). Let us know what you think, Tony, HS GC Group -- ---------------------------------------------------------------------- | Tony Printezis, Staff Engineer | Sun Microsystems Inc. | | | MS BUR02-311 | | e-mail: tony.printezis(a)sun.com | 35 Network Drive | | office: +1 781 442 0998 (x20998) | Burlington, MA01803-0902, USA | ---------------------------------------------------------------------- e-mail client: Thunderbird (Solaris)

6 14

What values do use for MaxTenuringThreshold?
by Tony Printezis 30 May '08

30 May '08

(this is a follow-up to a discussion on the hotspot-gc-dev list) We're trying to take a quick poll on what values you use for MaxTenuringThreshold and whether the decrease in age field size from 5 to 4 bits (from 1.5u6) seemed to have affected the performance of your app. This is the thread, if you're interested: http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2008-May/000309.html Tony, HS GC Group -- ---------------------------------------------------------------------- | Tony Printezis, Staff Engineer | Sun Microsystems Inc. | | | MS BUR02-311 | | e-mail: tony.printezis(a)sun.com | 35 Network Drive | | office: +1 781 442 0998 (x20998) | Burlington, MA01803-0902, USA | ---------------------------------------------------------------------- e-mail client: Thunderbird (Solaris) _______________________________________________ hotspot-gc-use mailing list hotspot-gc-use(a)openjdk.java.net http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

3 5

GC Timestamps in Java 6
by Nicolas Michael 30 May '08

30 May '08

Hi, you have introduced some additional timestamps in the gc logs with Java 6, showing cpu time (user and system) as well as elapsed time. When I ran some CMS tests where I changed the number of CMS threads, I've noticed that those numbers don't show what I originally expected... For a STW collection, this new output is quite nice: 966.697: [GC 966.698: [ParNew: 260292K->65536K(262144K), 0.1426038 secs] 1090657K->898209K(1368064K), 0.1429749 secs] [Times: user=1.88 sys=0.06, real=0.14 secs] The collection took 0.14 secs, and the ParNew threads consumed 1.88+0.06=1.94 seconds cpu time. With 16 ParNew threads that I had configured, each single thread was therefore on a cpu for most of the time (they consumed 1.94 out of 16*0.14=2.24 theoretically possible cpu seconds). That's nice to know! However, for concurrent activities, this output is a little confusing: 2319.981: [CMS-concurrent-mark: 3.487/3.487 secs] [Times: user=54.12 sys=0.78, real=3.49 secs] The concurrent mark took 3.49 seconds, ok. Now I would expect the "user" and "sys" times to reflect the cpu time consumed for concurrent marking (the sum over all parallel CMS threads). In this example, I had 8 parallel CMS threads configured (plus the "coordinator" CMS thread). But 9 threads cannot consume 55 cpu seconds within 3.5 real seconds. So I guess this cpu time reported as "user" and "sys" is consumed by *all* threads of the JVM, including the mutator threads. Which would make sense (the numbers would fit), but is a rather meaningless information... Probably it is intended that way. But I think those times would be more usefull if they reflected *only* the gc activities. When I look at a gc log, I would like to see how much time (elapsed as well as cpu cycles) are spent for *garbage collection*, without cpu time spent for my mutator threads. What do you think? Nick. PS: Thanks Tony for pointing me to this discussion list!

3 4

hg: jdk7/hotspot-gc/hotspot: 6706662: Remove workaround introduced in fix for 6624782
by jon.masamitsu＠sun.com 28 May '08

28 May '08

Changeset: 23a06eca8e83 Author: jmasa Date: 2008-05-27 11:46 -0700 URL: http://hg.openjdk.java.net/jdk7/hotspot-gc/hotspot/rev/23a06eca8e83 6706662: Remove workaround introduced in fix for 6624782 Summary: Remove workaround compiler options for instanceKlass.cpp and objArrayKlass.cpp. Reviewed-by: ysr, jcoomes ! make/solaris/makefiles/amd64.make

1 0

hg: jdk7/hotspot-gc/hotspot: 4 new changesets
by igor.veresov＠sun.com 21 May '08

21 May '08

Changeset: f3de1255b035 Author: rasbold Date: 2008-05-07 08:06 -0700 URL: http://hg.openjdk.java.net/jdk7/hotspot-gc/hotspot/rev/f3de1255b035 6603011: RFE: Optimize long division Summary: Transform long division by constant into multiply Reviewed-by: never, kvn ! src/cpu/x86/vm/x86_64.ad ! src/share/vm/opto/classes.hpp ! src/share/vm/opto/divnode.cpp ! src/share/vm/opto/mulnode.cpp ! src/share/vm/opto/mulnode.hpp ! src/share/vm/opto/type.hpp ! src/share/vm/utilities/globalDefinitions.hpp Changeset: 7cce9e4e0f7c Author: rasbold Date: 2008-05-09 05:26 -0700 URL: http://hg.openjdk.java.net/jdk7/hotspot-gc/hotspot/rev/7cce9e4e0f7c Merge Changeset: 83c868b757c0 Author: jrose Date: 2008-05-14 00:41 -0700 URL: http://hg.openjdk.java.net/jdk7/hotspot-gc/hotspot/rev/83c868b757c0 6701024: SAJDI functionality is broken Summary: back out sa-related changes to 6652736, use concrete expressions for WKK names in the SA Reviewed-by: never, sundar ! agent/src/share/classes/sun/jvm/hotspot/memory/SystemDictionary.java ! src/share/vm/classfile/systemDictionary.hpp ! src/share/vm/runtime/vmStructs.cpp Changeset: 7a0a921a1a8c Author: rasbold Date: 2008-05-14 15:01 -0700 URL: http://hg.openjdk.java.net/jdk7/hotspot-gc/hotspot/rev/7a0a921a1a8c Merge

1 0

Bug 6700047
by Maslowski, Chuck 19 May '08

19 May '08

we ran into this HotSpot bug, do you guys have any information as to a circumvention or fix ? -- thanks Chuck Maslowski CBOE

2 1

Request for reviews (L): 6695810: null oop passed to encode_heap_oop_not_null
by Vladimir Kozlov 15 May '08

15 May '08

Note: diffs contains changes (in node.cpp and c2_globals.hpp) for 6701887 which I will push first. http://webrev.invokedynamic.info/kvn/6695810/index.html Fixed 6695810: null oop passed to encode_heap_oop_not_null These changes include fixes for problems found in Escape Analysis and Compressed Oops implementations. Also they include additional optimizations for Compressed Oops: - use the 32-bits gap after klass in a object for a narrow oop field, - use the 32-bits gap after klass in a object for boxing objects value (except Long and Double), - use heapOopSize for instanceKlass::_nonstatic_field_size value instead of wordSize, - add LoadNKlass and CMoveN nodes and use CmpN and ConN nodes and add correspondent platform specific assembler instructions to generate narrow oops (32-bits) compares for oop type and oop NULL checks. Reviewed by: Fix verified (y/n): y, failed tests and generated code Other testing: JPRT, CTW, nsk tests, refworkload

1 0

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

Re: Question about GCOverheadLimit
by Jon Masamitsu 12 May '08

12 May '08

The total time is measured as the time from the end of a full GC to the end of the next full GC. Adam Hawthorne wrote: > Hi all, > > I just have a quick question about the GC Overhead Limit. The docs say: if > more than 98% of the total time is spent in garbage collection and less than > 2% of the heap is recovered, an OutOfMemoryError will be thrown. > > What "total time" is it referring to there? > > Thanks, > > Adam > > > > ------------------------------------------------------------------------ > > _______________________________________________ > 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

1 0

hg: jdk7/hotspot-gc/hotspot: 6697534: Premature GC and invalid lgrp selection with NUMA-aware allocator.
by igor.veresov＠sun.com 09 May '08

09 May '08

Changeset: e3729351c946 Author: iveresov Date: 2008-05-09 16:34 +0400 URL: http://hg.openjdk.java.net/jdk7/hotspot-gc/hotspot/rev/e3729351c946 6697534: Premature GC and invalid lgrp selection with NUMA-aware allocator. Summary: Don't move tops of the chunks in ensure_parsibility(). Handle the situation with Solaris when a machine has a locality group with no memory. Reviewed-by: apetrusenko, jcoomes, ysr ! src/os/solaris/vm/os_solaris.cpp ! src/os/solaris/vm/os_solaris.hpp ! src/share/vm/gc_implementation/shared/mutableNUMASpace.cpp

1 0