December 2007 - hotspot-gc-dev

Perplexing GC Time Growth
by Jason Vasquez 31 Dec '07

31 Dec '07

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

1 0

HOARD
by Keith Holdaway 20 Dec '07

20 Dec '07

I researched HOARD: http://developers.sun.com/solaris/articles/multiproc/multiproc.html The Hoard memory allocator is a fast, scalable, and memory-efficient memory allocator. It runs on a variety of platforms, including Linux, Solaris, and Windows. Hoard is a drop-in replacement for malloc() that can dramatically improve application performance, especially for multithreaded programs running on multiprocessors. Is this purely an OS change; or does one have to make changes to the VM source to use HOARD instead of malloc etc? keith Keith R Holdaway Java Development Technologies<http://rdwss.na.sas.com/mti/jdt/default.aspx> SAS... The Power to Know Carpe Diem ...

5 4

equest for review (small): 6621728 "Heap inspection should not crash in the face of C-heap exhaustion"
by Y Srinivas Ramakrishna 17 Dec '07

17 Dec '07

[A set of patches as well as a gzipped tarball of the webrev is attached. Should your mail servers strip either of the attachments, you may manually access them from the archives of this mailing list. For those internal to Sun, a webrev pointer of these changes can be found off of the "Suggested Fix" section of the CR. Thanks a lot for your reviews!] ----------------------------- Fixed 6621728: Heap inspection should not crash in the face of C-heap exhaustion When requisite support data structures for accumulating the statistics cannot be allocated because of C-heap exhaustion, we now either simply refuse to compute the histogram information or report the extent of undercounting (depending on which allocation(s) did not succeed). [*] I also took the opportunity to clean up and consolidate some statistics reporting associated with CMS's free list spaces that came to light from a recent customer interaction. The changes directly related to the original bug are the first two files in the webrev (or in the patch file). The remaining files contain changes related to the clean-up in [*] above. Fix verified: yes Verification Testing: artificially injected allocation failures; tested +PrintClassHistogram with SPECjvm98; dumped FLS census data and checked formatting.

1 0

request for review: 6634032 (medium-to-small): CMS: Need CMSInitiatingPermOccupancyFraction for perm, divorcing from CMSInitiatingOccupancyFraction
by Y Srinivas Ramakrishna 10 Dec '07

10 Dec '07

[Attached is a patch of diffs as well as a webrev tar-ball, whichever format you prefer. The latter may be easier for the more extensive changes in the case of one of the files at least, where the diffs may get a bit hairy to read. Sun-internal reviewers can access the webrev via a pointer in the suggested fix section of the bug report.] 6634032 CMS: Need CMSInitiatingPermOccupancyFraction for perm, divorcing from CMSInitiatingOccupancyFraction In addition, we can now dynamically decide at the start of a CMS collection cycle whether we will be collecting the perm gen in that cycle. I introduced a couple of experimental knobs to tweak that decision policy, but left the default current policy intact (modulo the divorcing of the two collection thresholds). See the block comment preceding update_should_unload_classes(). The settings of the knobs will likely change based on further experiments and experience, but the current settings are so as to rock the boat as little as possible. This should fix the problems reported by Anuj Lal and Thomas Viessmann on this mailing list. (vide the following thread: http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2007-November/000081.… ) Further improvements are planned in CR 6543076 "Adaptive collection of perm gen", leveraging the infrastructure here to allow dynamic per-cycle decisions based on perm gen allocation rate estimates etc. Fix Verified: yes Verification Testing: +PrintGCDetails was used along with default and various non-default settings to verify that perm gen collections were occurring as designed. Other Testing: on-going internal testing (rwl and jprt); performance data will be collected and shared prior to any push. PS: mixed in with the diffs is an old diff for:- 6621144 CMS: assertion failure "is_cms_thread == Thread::current()->is_ConcurrentGC_thread()" which you can also review (or feel free to ignore for the purposes of this code review). Many thanks for your reviews, feedback, comments and suggestions. -- ramki

4 5

Please ignore in hotspot-gc-dev too
by Jon Masamitsu 06 Dec '07

06 Dec '07

hotspot-gc-use(a)openjdk.java.net is forwarded to hotspot-gc-dev(a)openjdk.java.net without moderation? On hotspot-gc-dev who is the sender? hotspot-gc-use(a)openjdk.java.net was added to the list of acceptable aliases. _______________________________________________ hotspot-gc-use mailing list hotspot-gc-use(a)openjdk.java.net http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

1 0

Please ignore
by Jon Masamitsu 06 Dec '07

06 Dec '07

hotspot-gc-use(a)openjdk.java.net is forwarded to hotspot-gc-dev(a)openjdk.java.net without moderation? On hotspot-gc-dev who is the sender? _______________________________________________ hotspot-gc-use mailing list hotspot-gc-use(a)openjdk.java.net http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

1 0

Please ignore
by Jon Masamitsu 06 Dec '07

06 Dec '07

hotspot-gc-use(a)openjdk.java.net is forwarded to hotspot-gc-dev(a)openjdk.java.net without moderation? _______________________________________________ hotspot-gc-use mailing list hotspot-gc-use(a)openjdk.java.net http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

1 0

PrintGCStats
by Ciciora, Paul 03 Dec '07

03 Dec '07

Since GC formats are constantly changing and different collectors log stats differently I'd love to so you adopt a harvestable output format. The idea would be to send stats to a separate file and use a name/value style format. That way you could send whatever you wanted there and all the harvester script or program would have to know is the tag name. The name could be terse to save space. You could register the tag names so open source changes would conform. If you did that then format changes to the human readable output could be separate. You wouldn't have to be as sensitive to breaking scripts. Just a thought. I'm probably not the first one to suggest this. -----Original Message----- From: hotspot-gc-dev-bounces(a)openjdk.java.net [mailto:hotspot-gc-dev-bounces@openjdk.java.net] On Behalf Of hotspot-gc-dev-request(a)openjdk.java.net Sent: Monday, December 03, 2007 2:00 PM To: hotspot-gc-dev(a)openjdk.java.net Subject: hotspot-gc-dev Digest, Vol 6, Issue 1 Send hotspot-gc-dev mailing list submissions to hotspot-gc-dev(a)openjdk.java.net To subscribe or unsubscribe via the World Wide Web, visit http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev or, via email, send a message with subject or body 'help' to hotspot-gc-dev-request(a)openjdk.java.net You can reach the person managing the list at hotspot-gc-dev-owner(a)openjdk.java.net When replying, please edit your Subject line so it is more specific than "Re: Contents of hotspot-gc-dev digest..." Today's Topics: 1. PrintGCStats (Naas, Dave) 2. Re: PrintGCStats (Peter B. Kessler) ---------------------------------------------------------------------- Message: 1 Date: Mon, 3 Dec 2007 10:57:30 -0600 From: "Naas, Dave" <naasd(a)cboe.com> Subject: PrintGCStats To: <hotspot-gc-dev(a)openjdk.java.net> Message-ID: <4BD174404CF4A34C98322DC926CF862B2289F2(a)MSMAIL.cboent.cboe.com> Content-Type: text/plain; charset="iso-8859-1" Regarding the posting from Oct 26, 2007: http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2007-October/00006 4.html where Mr. Kessler states: quote > > I'll see if we can get an updated version of PrintGCStats out to replace the ancient one available at > > <http://java.sun.com/developer/technicalArticles/Programming/turbo/> > > That should give you the kinds of statistics you are asking for. > > ... peter unquote I was wondering if a new version of PrintGCStats and PrintGCFixup will indeed be made available or if we should proceed with our own updates to handle new jdk releases, etc.?? A specific, recent example is jdk 1.6 with the -XX:PrintFLSStatistics flag. We have found that this setting prevents the current PrintGCStats from properly parsing ParNew data and thus doesn't generate the Promotion stats (Promo.csv file). The following snippet shows how the ParNew line is now split (shown in bold), thanks to the -XX:PrintFLSStatistics: ======================================================================== ======================================================================== ====== {Heap before GC invocations=0 (full 0): par new generation total 305088K, used 277376K [0x2f800000, 0x43d00000, 0x43d00000) eden space 277376K, 100% used [0x2f800000, 0x406e0000, 0x406e0000) from space 27712K, 0% used [0x406e0000, 0x406e0000, 0x421f0000) to space 27712K, 0% used [0x421f0000, 0x421f0000, 0x43d00000) concurrent mark-sweep generation total 2739200K, used 0K [0x43d00000, 0xeb000000, 0xeb000000) concurrent-mark-sweep perm gen total 131072K, used 14913K [0xeb000000, 0xf3000000, 0xfb000000) 8.746: [GC Before GC: Statistics for BinaryTreeDictionary: ------------------------------------ Total Free Space: 701235200 Max Chunk Size: 701235200 Number of Blocks: 1 Av. Block Size: 701235200 Tree Height: 1 Before GC: Statistics for BinaryTreeDictionary: ------------------------------------ Total Free Space: 0 Max Chunk Size: 0 Number of Blocks: 0 Tree Height: 0 8.746: [ParNew Desired survivor size 14188544 bytes, new threshold 1 (max 4) - age 1: 15763640 bytes, 15763640 total - age 2: 56 bytes, 15763696 total : 277376K->15474K(305088K), 0.5657873 secs] 277376K->15474K(3044288K)After GC: Statistics for BinaryTreeDictionary: ------------------------------------ Total Free Space: 701218816 Max Chunk Size: 701218816 Number of Blocks: 1 Av. Block Size: 701218816 Tree Height: 1 After GC: Statistics for BinaryTreeDictionary: ------------------------------------ Total Free Space: 0 Max Chunk Size: 0 Number of Blocks: 0 Tree Height: 0 , 0.5668866 secs] [Times: user=0.34 sys=1.07, real=0.57 secs] ======================================================================== ======================================================================== ====== Thank you, Dave David Naas Chicago Board Options Exchange 312-786-7222 ------------------------------ Message: 2 Date: Mon, 03 Dec 2007 10:19:41 -0800 From: "Peter B. Kessler" <Peter.Kessler(a)Sun.COM> Subject: Re: PrintGCStats To: "Naas, Dave" <naasd(a)cboe.com> Cc: hotspot-gc-dev(a)openjdk.java.net Message-ID: <475448BD.3030401(a)Sun.COM> Content-Type: text/plain; format=flowed; charset=ISO-8859-1 It looks like the most recent PrintGCFixup (and PrintGCStats and CompareGCStats) is "posted" in http://permalink.gmane.org/gmane.comp.java.openjdk.hotspot.gc.devel/51 You have to join all the lines that got wrapped (sigh). Sometimes you have to run PrintGCFixup more than once to get it to remove things so that it can see other things to remove. Though, in your case, running it twice doesn't help remove the output of PrintFLSStatistics. It does look like if you add a cleaner for PrintFLSStatistics, you'll have to run PrintGCFixup at least twice, since that output gets in the way of the removal of the PrintTenuringDistribution flag. PrintGCFixup and friends look like a prime candidate for putting in hotspot/tools/ and letting people make improvements. If you wanted to contribute your addition for removing PrintFLSStatistics, I'm sure we could find someone here to sponsor it. ... peter Naas, Dave wrote: > Regarding the posting from Oct 26, 2007: http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2007-October/00006 4.html > where Mr. Kessler states: > quote > > > I'll see if we can get an updated version of PrintGCStats out to replace the ancient one available at > > > <http://java.sun.com/developer/technicalArticles/Programming/turbo/> > > > That should give you the kinds of statistics you are asking for. > > > ... peter > unquote > > I was wondering if a new version of PrintGCStats and PrintGCFixup will indeed be made available or if we should proceed with our own updates to handle new jdk releases, etc.?? > > A specific, recent example is jdk 1.6 with the -XX:PrintFLSStatistics flag. We have found that this setting prevents the current PrintGCStats from properly parsing ParNew data and thus doesn't generate the Promotion stats (Promo.csv file). The following snippet shows how the ParNew line is now split (shown in bold), thanks to the -XX:PrintFLSStatistics: > > ======================================================================== ======================================================================== ====== > {Heap before GC invocations=0 (full 0): > par new generation total 305088K, used 277376K [0x2f800000, 0x43d00000, 0x43d00000) > eden space 277376K, 100% used [0x2f800000, 0x406e0000, 0x406e0000) > from space 27712K, 0% used [0x406e0000, 0x406e0000, 0x421f0000) > to space 27712K, 0% used [0x421f0000, 0x421f0000, 0x43d00000) > concurrent mark-sweep generation total 2739200K, used 0K [0x43d00000, 0xeb000000, 0xeb000000) > concurrent-mark-sweep perm gen total 131072K, used 14913K [0xeb000000, 0xf3000000, 0xfb000000) > 8.746: [GC Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 701235200 > Max Chunk Size: 701235200 > Number of Blocks: 1 > Av. Block Size: 701235200 > Tree Height: 1 > Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 0 > Max Chunk Size: 0 > Number of Blocks: 0 > Tree Height: 0 > 8.746: [ParNew > Desired survivor size 14188544 bytes, new threshold 1 (max 4) > - age 1: 15763640 bytes, 15763640 total > - age 2: 56 bytes, 15763696 total > : 277376K->15474K(305088K), 0.5657873 secs] 277376K->15474K(3044288K)After GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 701218816 > Max Chunk Size: 701218816 > Number of Blocks: 1 > Av. Block Size: 701218816 > Tree Height: 1 > After GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 0 > Max Chunk Size: 0 > Number of Blocks: 0 > Tree Height: 0 > , 0.5668866 secs] [Times: user=0.34 sys=1.07, real=0.57 secs] > ======================================================================== ======================================================================== ====== > > Thank you, > Dave > > David Naas > Chicago Board Options Exchange > 312-786-7222 > End of hotspot-gc-dev Digest, Vol 6, Issue 1 ********************************************

2 3

PrintGCStats
by Naas, Dave 03 Dec '07

03 Dec '07

Regarding the posting from Oct 26, 2007: http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2007-October/000064.h… where Mr. Kessler states: quote > > I'll see if we can get an updated version of PrintGCStats out to replace the ancient one available at > > <http://java.sun.com/developer/technicalArticles/Programming/turbo/> > > That should give you the kinds of statistics you are asking for. > > ... peter unquote I was wondering if a new version of PrintGCStats and PrintGCFixup will indeed be made available or if we should proceed with our own updates to handle new jdk releases, etc.?? A specific, recent example is jdk 1.6 with the -XX:PrintFLSStatistics flag. We have found that this setting prevents the current PrintGCStats from properly parsing ParNew data and thus doesn't generate the Promotion stats (Promo.csv file). The following snippet shows how the ParNew line is now split (shown in bold), thanks to the -XX:PrintFLSStatistics: ====================================================================================================================================================== {Heap before GC invocations=0 (full 0): par new generation total 305088K, used 277376K [0x2f800000, 0x43d00000, 0x43d00000) eden space 277376K, 100% used [0x2f800000, 0x406e0000, 0x406e0000) from space 27712K, 0% used [0x406e0000, 0x406e0000, 0x421f0000) to space 27712K, 0% used [0x421f0000, 0x421f0000, 0x43d00000) concurrent mark-sweep generation total 2739200K, used 0K [0x43d00000, 0xeb000000, 0xeb000000) concurrent-mark-sweep perm gen total 131072K, used 14913K [0xeb000000, 0xf3000000, 0xfb000000) 8.746: [GC Before GC: Statistics for BinaryTreeDictionary: ------------------------------------ Total Free Space: 701235200 Max Chunk Size: 701235200 Number of Blocks: 1 Av. Block Size: 701235200 Tree Height: 1 Before GC: Statistics for BinaryTreeDictionary: ------------------------------------ Total Free Space: 0 Max Chunk Size: 0 Number of Blocks: 0 Tree Height: 0 8.746: [ParNew Desired survivor size 14188544 bytes, new threshold 1 (max 4) - age 1: 15763640 bytes, 15763640 total - age 2: 56 bytes, 15763696 total : 277376K->15474K(305088K), 0.5657873 secs] 277376K->15474K(3044288K)After GC: Statistics for BinaryTreeDictionary: ------------------------------------ Total Free Space: 701218816 Max Chunk Size: 701218816 Number of Blocks: 1 Av. Block Size: 701218816 Tree Height: 1 After GC: Statistics for BinaryTreeDictionary: ------------------------------------ Total Free Space: 0 Max Chunk Size: 0 Number of Blocks: 0 Tree Height: 0 , 0.5668866 secs] [Times: user=0.34 sys=1.07, real=0.57 secs] ====================================================================================================================================================== Thank you, Dave David Naas Chicago Board Options Exchange 312-786-7222

2 1