tag:blogger.com,1999:blog-7735872642513631302.post3022185187901519315..comments2023-07-15T17:54:51.492+01:00Comments on Alexey Ragozin: Java GC, HotSpot's CMS and heap fragmentationAlexey Ragozinhttp://www.blogger.com/profile/13720493857045012756noreply@blogger.comBlogger22125tag:blogger.com,1999:blog-7735872642513631302.post-58767391170252673292015-10-06T12:12:39.663+01:002015-10-06T12:12:39.663+01:00Hi Alexey,
one application leads to 100% CPU, We ...Hi Alexey,<br /><br />one application leads to 100% CPU, We have the following jvm parameters :<br /><br />-server<br />-d64<br />-Xms2048M<br />-Xmx2048M<br />-XX:+DisableExplicitGC<br />-XX:NewSize=512M<br />-XX:MaxNewSize=512M<br />-XX:SurvivorRatio=4<br />-XX:PermSize=256M<br />-XX:MaxPermSize=256M<br />-XX:+UseParNewGC<br />-XX:+UseConcMarkSweepGC<br />-XX:CMSInitiatingOccupancyFraction=65<br />-XX:+UseCMSInitiatingOccupancyOnly<br />-XX:+CMSPermGenSweepingEnabled<br />-XX:MaxTenuringThreshold=30<br /><br /><br />Thread dump stack shows:<br /><br />Heap<br /> par new generation total 436928K, used 93221K [0x00000006b0000000, 0x00000006d0000000, 0x00000006d0000000)<br /> eden space 349568K, 21% used [0x00000006b0000000, 0x00000006b484f438, 0x00000006c5560000)<br /> from space 87360K, 21% used [0x00000006c5560000, 0x00000006c681a020, 0x00000006caab0000)<br /> to space 87360K, 0% used [0x00000006caab0000, 0x00000006caab0000, 0x00000006d0000000)<br /> concurrent mark-sweep generation total 4718592K, used 3590048K [0x00000006d0000000, 0x00000007f0000000, 0x00000007f0000000)<br /> concurrent-mark-sweep perm gen total 262144K, used 217453K [0x00000007f0000000, 0x0000000800000000, 0x0000000800000000)<br /><br /> CMS: abort preclean due to time 2015-09-24T14:16:14.752+0200: 4505865.908: [CMS-concurrent-abortable-preclean: 4.332/5.134 secs] [Times: user=5.22 sys=0.08, real=5.14 secs]<br />2015-09-24T14:16:14.756+0200: 4505865.912: [GC[YG occupancy: 127725 K (436928 K)]4505865.912: [Rescan (parallel) , 0.0602290 secs]4505865.973: [weak refs processing, 0.0000220 secs] [1 CMS-remark: 3590048K(4718592K)] 3717774K(5155520K), 0.0604150 secs] [Times: user=0.64 sys=0.00, real=0.06 secs]<br /><br /><br />Can u help me in understanding this issue?<br />Anonymousnoreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-89480802191216079162015-03-12T06:08:30.488+00:002015-03-12T06:08:30.488+00:00BTW -Xmx should be same as -Xms. That could be one...BTW -Xmx should be same as -Xms. That could be one source of problems.Alexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-11764633370422163412015-03-12T06:04:27.387+00:002015-03-12T06:04:27.387+00:00JVM options sounds reasonable in general. It doesn...JVM options sounds reasonable in general. It doesn't they are reasonable for your application.<br />I would suggest you to post this question on StackOvervflow. I would also ask you to add some description of application and GC logs between two full GCAlexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-12961350443204461782015-03-11T10:57:02.657+00:002015-03-11T10:57:02.657+00:00Hi Alexey,
We have the following options set:
-...Hi Alexey,<br /><br />We have the following options set:<br /> -Xmx50g -server -XX:NewSize=4g -XX:MaxNewSize=4g -Xms40g -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:CMSInitiatingOccupancyFraction=70 -XX:+UseCMSInitiatingOccupancyOnly -XX:MaxTenuringThreshold=2 -XX:SurvivorRatio=8 -XX:+UnlockDiagnosticVMOptions -XX:ParGCCardsPerStrideChunk=32768 -XX:+UseGCTaskAffinity -XX:+BindGCTaskThreadsToCPUs -XX:+CMSScavengeBeforeRemark -XX:+CMSConcurrentMTEnabled -XX:+CMSParallelRemarkEnabled -XX:+ParallelRefProcEnabled -XX:+CMSClassUnloadingEnabled -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:PrintFLSStatistics=1 <br /><br />We see CMS running into heap fragmentation issue a few times a day and then CMS takes about 40 seconds to do GC during those times. Are we doing something wrong here? Anonymousnoreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-5651087307430359782014-10-17T16:09:47.424+01:002014-10-17T16:09:47.424+01:00Thanks a lot for this blog Alexey.
I saw few mil...Thanks a lot for this blog Alexey. <br /><br />I saw few million logs in our log file written by JVM "Live object size n". <br /> Below are the flags enabled. Do you know which flag will result in printing millions of "live object sizes" Thanks. <br /><br />/usr/java/bin/java -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xincgc <br />-XX:NewSize=256m -XX:MaxNewSize=256m <br /> -XX:-UseBiasedLocking -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime <br /> -XX:PrintCMSStatistics=1 <br /> -XX:+PrintTenuringDistribution <br /> -XX:+PrintReferenceGC <br /> -XX:+PrintJNIGCStalls <br /> -XX:+PrintCMSInitiationStatistics <br /> -XX:+CMSDumpAtPromotionFailure <br /> -XX:+PrintPromotionFailure <br />Logs:<br /><br />0x000000077f200278: live object of size 5<br /><br />0x000000077f2002a0: live object of size 4Srujan kumar Gullahttps://www.blogger.com/profile/07575533045732729938noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-17490766370781788092014-08-19T06:39:57.403+01:002014-08-19T06:39:57.403+01:00I mean your Xmx should be large enough to accommod...I mean your Xmx should be large enough to accommodate both objects and work buffer for CMS.<br /><br />-XX:CMSInitiatingOccupancyFraction cotrols when old GC cycle starts. But if old space is full of live object it will not free much.Alexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-36388926919484992272014-08-16T05:43:52.878+01:002014-08-16T05:43:52.878+01:00What do you mean by provide enough buffer room to ...What do you mean by provide enough buffer room to CMS ? Are you referring by having lesser fraction we will give enough buffer room to CMS ? i.e -XX:CMSInitiatingOccupancyFraction=30Anonymoushttps://www.blogger.com/profile/08793505183247022474noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-29303502503238800342014-03-07T02:49:28.252+00:002014-03-07T02:49:28.252+00:00Hi,
http://www.oracle.co...jsp-135488.html states...Hi,<br /><br />http://www.oracle.co...jsp-135488.html states clearly that G1 is a compacting collector. <br /><br />However, Are thee any tools or log options which would allow us to observe memory fragmentation, to ensure that G1 is indeed compacting memory? <br /><br />If there is one, how to use to observe memory fragmentation. <br /><br />Thanks in advance. Anonymoushttps://www.blogger.com/profile/03238822173684482969noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-48769576107366241262013-09-13T09:43:45.269+01:002013-09-13T09:43:45.269+01:00Hi,
Looks strange indeed. What is CPU utilization...Hi,<br /><br />Looks strange indeed. What is CPU utilization on server during this pause? Is it possible what it starving on CPU.<br /><br />Another reason could be some safe point issue, I would recommend you to enable logging safe point statistics. Alexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-35685335930925748402013-09-12T22:39:22.061+01:002013-09-12T22:39:22.061+01:00Hi Alexey,
We are running into a strange issue:
...Hi Alexey,<br /><br />We are running into a strange issue:<br /><br />2013-09-12T10:08:02.253-0700: 120913.045: [GC Before GC:<br />Statistics for BinaryTreeDictionary:<br />------------------------------------<br />Total Free Space: 37142932<br />Max Chunk Size: 19517862<br />Number of Blocks: 20<br />Av. Block Size: 1857146<br />Tree Height: 8<br />Before GC:<br />Statistics for BinaryTreeDictionary:<br />------------------------------------<br />Total Free Space: 3619112<br />Max Chunk Size: 3617792<br />Number of Blocks: 3<br />Av. Block Size: 1206370<br />Tree Height: 2<br />120913.045: [ParNew120933.884: [SoftReference, 0 refs, 0.0000055 secs]120933.884: [WeakReference, 156 refs, 0.0000244 secs]120933.884: [FinalReference, 6 refs, 0.0000115 secs]120933.884: [PhantomReference, 61 refs, 0.0000094 secs]120933.884: [JNI Weak Reference, 0.0000013 secs]: 59008K->6528K(59008K), 20.8394227 secs] 895484K->846135K(1042048K)After GC:<br />Statistics for BinaryTreeDictionary:<br />------------------------------------<br />Total Free Space: 36263548<br />Max Chunk Size: 19517862<br />Number of Blocks: 19<br />Av. Block Size: 1908607<br />Tree Height: 8<br />After GC:<br />Statistics for BinaryTreeDictionary:<br />------------------------------------<br />Total Free Space: 3619112<br />Max Chunk Size: 3617792<br />Number of Blocks: 3<br />Av. Block Size: 1206370<br />Tree Height: 2<br />, 20.8399181 secs] [Times: user=0.70 sys=0.03, real=20.86 secs] <br /><br />[Times: user=0.70 sys=0.03, real=20.86 secs] seems to indicate a swapping failure. But we have a Windows 2003 server with 8GB RAM (with PAE) with committed bytes in 28 to 30% range. <br /><br />Could you please suggest what could be going wrong here.<br /><br />Regards,<br />Avinash<br /><br /><br />Anonymousnoreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-31915409292196574232013-09-03T19:43:15.891+01:002013-09-03T19:43:15.891+01:00Bug is http://bugs.sun.com/bugdatabase/view_bug.do...Bug is http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=2207828<br /><br />But it looks like I was wrong, it is reported to be fixed at 6u27Alexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-11136878035989889522013-09-03T15:09:09.784+01:002013-09-03T15:09:09.784+01:00Hi Alexey
May I ask you which bug you are referri...Hi Alexey<br /><br />May I ask you which bug you are referring to? I have looked at http://www.oracle.com/technetwork/java/javase/documentation/overview-156328.html, but haven't found anything. <br /><br />Kind regards,<br />MortenMorten Knudsennoreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-37908836887770490902013-08-31T22:19:32.132+01:002013-08-31T22:19:32.132+01:00Hi,
1. I would recommend you to upgrade JVM versi...Hi,<br /><br />1. I would recommend you to upgrade JVM version, if I remember correctly there were bug in parallel processing of references in CMS prior 6u34<br /><br />2. Your case looks like fragmentation issue. So far only two remedies I know for this problem: restart JVM regulary and increase heap size (this would increase mean time to promotion failure)Alexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-71205178380384274902013-08-28T04:07:09.203+01:002013-08-28T04:07:09.203+01:00Alexey, I am having the both errors on my applicat...Alexey, I am having the both errors on my application: concurrent mode failure & Promotion failed.<br /><br />Here is my log: 2013-08-27T16:59:53.952-0500: 201564.214: [GC 201564.214: [ParNew202182.528: [SoftReference, 0 refs, 0.0000110 secs]202182.528: [WeakReference, 1015 refs, 0.0001720 secs]202182.528: [FinalReference, 1625 refs, 0.0025210 secs]202182.531: [PhantomReference, 1 refs, 0.0000050 secs]202182.531: [JNI Weak Reference, 0.0000100 secs] (promotion failed): 3774912K->3774912K(3774912K), 619.3859950 secs]202183.600: [CMS CMS: abort preclean due to time 2013-08-27T17:10:14.937-0500: 202185.199: [CMS-concurrent-abortable-preclean: 7.271/626.671 secs] [Times: user=699.20 sys=98.95, real=626.55 secs]<br /> (concurrent mode failure)202189.179: [SoftReference, 614 refs, 0.0000710 secs]202189.179: [WeakReference, 5743 refs, 0.0007600 secs]202189.180: [FinalReference, 3380 refs, 0.0004430 secs]202189.180: [PhantomReference, 212 refs, 0.0000260 secs]202189.180: [JNI Weak Reference, 0.0000180 secs]: 8328471K->4813636K(8388608K), 18.5940310 secs] 11323577K->4813636K(12163520K), [CMS Perm : 208169K->208091K(346920K)], 637.9802050 secs] [Times: user=705.47 sys=98.79, real=637.85 secs]<br />Total time for which application threads were stopped: 637.9820120 seconds<br /><br />Could you advise for the jvm parameter tuning?<br /><br />Here my server information:<br />-Xmx12288m <br />-Xms12288m <br />-XX:MaxPermSize=1024m <br />-XX:MaxNewSize=4096m <br />-XX:InitialCodeCacheSize=128m <br />-XX:ReservedCodeCacheSize=256m <br />-XX:+UseCodeCacheFlushing <br />-XX:+UseParNewGC <br />-XX:+UseConcMarkSweepGC <br />-XX:+CMSParallelRemarkEnabled <br />-XX:+CMSClassUnloadingEnabled <br />-XX:+UseCodeCacheFlushing <br />-XX:+OptimizeStringConcat <br />-XX:+UseTLAB <br />-XX:+ResizeTLAB <br />-XX:TLABSize=512k <br />-XX:+PrintGC <br />-XX:+DisableExplicitGC <br />-XX:+PrintGCDetails <br />-XX:-PrintConcurrentLocks <br />-XX:+PrintGCDateStamps <br />-XX:+PrintGCTimeStamps <br />-XX:+PrintReferenceGC <br />-XX:+PrintJNIGCStalls <br />-XX:+PrintGCApplicationStoppedTime <br />-XX:+CMSScavengeBeforeRemark <br />-XX:ConcGCThreads=12 <br />-XX:ParallelGCThreads=12<br /><br />I have 24 CPU Intel(R) Xeon(R) CPU X5650 @ 2.67GHz in my machine, RAM: 24675112 kB JDK version: java version "1.6.0_32"bearbearhttps://www.blogger.com/profile/00349656110189642621noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-45043974367828830182012-09-12T15:23:52.735+01:002012-09-12T15:23:52.735+01:00You seems to be allocating pretty large objects (y...You seems to be allocating pretty large objects (your log references 4MiB and 8MiB block allocation failure). Free lists are not covering such large objects.<br /><br />I have two guesses:<br />1. You have very big HashMap or several (couple millions of keys) and failure is causes by hash table resize.<br />2. You are allocating large arrays frequently.<br /><br />In first key, you should reserve enough capacity in HashMap on creation to avoid further resizes.<br />In second case, only increasing heap size would probably help.<br /><br />Any way analyzing heap dump should help you understand your memory occupation.Alexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-22470026772984965682012-09-12T04:51:26.053+01:002012-09-12T04:51:26.053+01:00Hi Alexey,
I have gone through your blogs and they...Hi Alexey,<br />I have gone through your blogs and they are an excellent source of rich information on GC patterns in Java. We are running into to some serious issues with the GCs in our production environment where we are seeing numerous, back to back promotion failures. We are using JDK 1.6.0_24 and below are the JVM settings. I am desperate for any help you can provide. Thanks in advance!<br /><br />- Vasanth<br /><br />-XX:PermSize=256m -XX:MaxPermSize=256m -XX:NewSize=512m -XX:MaxNewSize=512m -XX:SurvivorRatio=8 -XX:+DisableExplicitGC -Xms2560m -Xmx2560m -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC -verbose:gc -XX:+HeapDumpOnOutOfMemoryError -XX:ParallelGCThreads=12 -Dweblogic.SocketReaders=12 -XX:-UseBiasedLocking -XX:LargePageSizeInBytes=128m -XX:-UseThreadPriorities -Dnetworkaddress.cache.ttl=180 -XX:+PrintGCTimeStamps -XX:CMSInitiatingOccupancyFraction=60 -XX:+UseCMSInitiatingOccupancyOnly -XX:+PrintPromotionFailure -XX:PrintFLSStatistics=1<br /><br />Excerpts from GC logs showing promotion failures:<br /><br />47966.117: [ParNew (9: promotion failure size = 4997124) (promotion failed): 455476K->455653K(471872K), 0.0703983 secs]47966.188: [CMSCMS: Large block 0x8af1b6f0<br />: 1221978K->515117K(2097152K), 15.4494470 secs] 1667493K->515117K(2569024K), [CMS Perm : 177716K->174905K(262144K)]After GC:<br />Statistics for BinaryTreeDictionary:<br />------------------------------------<br />Total Free Space: 404984388<br />Max Chunk Size: 404984388<br />Number of Blocks: 1<br />Av. Block Size: 404984388<br />Tree Height: 1<br />After GC:<br />Statistics for BinaryTreeDictionary:<br />------------------------------------<br />Total Free Space: 0<br />Max Chunk Size: 0<br />Number of Blocks: 0<br />Tree Height: 0<br />, 15.5235571 secs] [Times: user=17.57 sys=0.06, real=15.52 secs] <br /><br />48225.553: [ParNew (10: promotion failure size = 8083460) (promotion failed): 457342K->457341K(471872K), 0.0770736 secs]48225.630: [CMSCMS: Large block 0xd89239b8<br />48226.011: [CMS-concurrent-sweep: 2.528/2.825 secs] [Times: user=7.61 sys=0.10, real=2.83 secs] <br /> (concurrent mode failure)CMS: Large block 0x8afc35d8<br />: 1701999K->515789K(2097152K), 14.7651760 secs] 2143373K->515789K(2569024K), [CMS Perm : 175107K->175061K(262144K)]After GC:<br />Statistics for BinaryTreeDictionary:<br />------------------------------------<br />Total Free Space: 404812426<br />Max Chunk Size: 404812426<br />Number of Blocks: 1<br />Av. Block Size: 404812426<br />Tree Height: 1<br />After GC:<br />Statistics for BinaryTreeDictionary:<br />------------------------------------<br />Total Free Space: 0<br />Max Chunk Size: 0<br />Number of Blocks: 0<br />Tree Height: 0<br />, 14.8443607 secs] [Times: user=15.40 sys=0.04, real=14.85 secs] <br />Vasanthhttps://www.blogger.com/profile/11436296523909274534noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-77274570614463531072012-07-07T18:04:58.792+01:002012-07-07T18:04:58.792+01:00It was really nice to study your post. I collect s...It was really nice to study your post. I collect some good points here. I would like to be appreciative you with the hard work you have made in skill this is great article.Content management systemhttp://instacms.comnoreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-34316442249084571562011-12-06T03:09:29.848+00:002011-12-06T03:09:29.848+00:00Hello Alexey -- Thanks for the blogs.
I read this...Hello Alexey -- Thanks for the blogs. <br />I read this article further, I think it's great.Nicolas AScanio Peñahttps://www.blogger.com/profile/10933729145834926714noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-5874437772549850092011-10-20T12:20:05.084+01:002011-10-20T12:20:05.084+01:00Ramki,
Thank you, for clarification. I will updat...Ramki,<br /><br />Thank you, for clarification. I will update post, but want spent sometime to better understand CMS allocation buffers fisrt.<br /><br />In mean time, I have published results from my tests http://aragozin.blogspot.com/2011/10/cms-heap-fragmentation-follow-up-1.htmlAlexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-13986888485519171262011-10-19T20:41:45.828+01:002011-10-19T20:41:45.828+01:00Hi Alexey -- Thanks for confirming that the fragme...Hi Alexey -- Thanks for confirming that the fragmentation is worse with use of "PLABs" in<br />the old generation, even after the fix for 6999988.<br /><br />I'd like to point out though, one small inaccuracy in your description of the use of "PLABs" for the CMS old space when allocating small blocks. As you know, the small blocks come from per-size free lists indexed by size. This pool is, of course, populated, when empty by means of allocating a large block that is a multiple of the small block size list that we are trying to allocate out of and carving it into a number of smaller blocks. However, this populating of free lists is orthogonal to the PLAB allocation in the sense that some subset of these are then removed from the global pool and added to the per-thread cache. This cache of free blocks of various sizes constitutes the PLAB from which a specific thread will allocate. The number of blocks that will be fetched into this PLAB is dynamically adjusted based on perceived recent demand, suitably averaged over the set of GC worker threads, and low-pass filtered to avoid large fluctuations. Thus, in steady state conditions the number that are fetched into the local cache should closely track the number allocated in each scavenge. By setting OldPLABSize to 16 and turning off dynamic resizing of this parameter, one could lead to excess inventory lying around in the caches and the global free pool.<br /><br />One final note. OldPLABSize is interpreted in CMS as not the size of the PLAB in words, but rather the number of free blocks of a given size that are used when replenishing the local per-worker free list caches.<br /><br />I agree that any changes in these parameters should be done with the utmost care for the reasons you provide. We have a number of customers who saw improved scavenge times as well as improved fragmentation behaviour as a result of the changes in 6631166+6699988.<br /><br />Thanks again for your well thought out and well-written blogs!<br /><br />-- ramkiikmarhttps://www.blogger.com/profile/07006454596707301742noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-12449923723219284102011-10-19T01:12:09.827+01:002011-10-19T01:12:09.827+01:00Hi Ramki,
Very interesting note.
I was using JDK ...Hi Ramki,<br /><br />Very interesting note.<br />I was using JDK 6u26 in may tests. I have repeated my test with 6u24. Indeed, it have shown much more frequent promotion failure events compared to 6u26.<br /><br />Regards,<br />AlexeyAlexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-44039682108855924172011-10-18T19:34:38.874+01:002011-10-18T19:34:38.874+01:00Hi Alexey -- Thanks for the blogs. Which JVM versi...Hi Alexey -- Thanks for the blogs. Which JVM version were you using in your experiments? Are you aware of Sun CR 6999988 ? As far as I can tell, this is fixed in 6u25 / hs20 for the first time. The existence of that bug led to all of the "sophisticated machinery" introduced in 6631166 being ineffective.<br /><br />thanks.<br />-- ramkiikmarhttps://www.blogger.com/profile/07006454596707301742noreply@blogger.com