November 2014 - hotspot-gc-dev

[JDK 6u21]: does CMS report concurrent mode failure on perm gen expansion ?
by Charlie Hunt 05 Dec '18

05 Dec '18

I'm looking at a GC log and surprised by the "concurrent mode failure" messages. I'm seeing the following GC log entries as the first 8 GCs: 3.398: [Full GC 3.398: [CMS (concurrent mode failure)[YG occupancy: 594957 K (1887488 K)]3.489: [weak refs processing, 0.0000140 secs]: 0K->0K(6291456K), 0.1308660 secs] 594957K->594957K(8178944K), [CMS Perm : 21247K->21247K(21248K)], 0.1310260 secs] [Times: user=0.13 sys=0.03, real=0.14 secs] 3.529: [Full GC 3.529: [CMS (concurrent mode failure)[YG occupancy: 594957 K (1887488 K)]3.617: [weak refs processing, 0.0000110 secs]: 0K->0K(6291456K), 0.1010290 secs] 594957K->594957K(8178944K), [CMS Perm : 21248K->21248K(42496K)], 0.1011530 secs] [Times: user=0.12 sys=0.00, real=0.10 secs] 3.638: [Full GC 3.638: [CMS (concurrent mode failure)[YG occupancy: 662071 K (1887488 K)]3.730: [weak refs processing, 0.0000140 secs]: 0K->0K(6291456K), 0.1068710 secs] 662071K->662071K(8178944K), [CMS Perm : 21319K->21319K(42688K)], 0.1069610 secs] [Times: user=0.15 sys=0.00, real=0.11 secs] 3.772: [Full GC 3.772: [CMS (concurrent mode failure)[YG occupancy: 729184 K (1887488 K)]3.915: [weak refs processing, 0.0000140 secs]: 0K->0K(6291456K), 0.1582170 secs] 729184K->729184K(8178944K), [CMS Perm : 21499K->21499K(42880K)], 0.1583500 secs] [Times: user=0.20 sys=0.00, real=0.16 secs] 3.962: [Full GC 3.962: [CMS (concurrent mode failure)[YG occupancy: 804686 K (1887488 K)]4.107: [weak refs processing, 0.0000130 secs]: 0K->0K(6291456K), 0.1598050 secs] 804686K->804686K(8178944K), [CMS Perm : 21702K->21702K(43072K)], 0.1599420 secs] [Times: user=0.21 sys=0.00, real=0.16 secs] 4.497: [Full GC 4.497: [CMS (concurrent mode failure)[YG occupancy: 939150 K (1887488 K)]4.672: [weak refs processing, 0.0000130 secs]: 0K->0K(6291456K), 0.1895350 secs] 939150K->939150K(8178944K), [CMS Perm : 22202K->22202K(43408K)], 0.1896680 secs] [Times: user=0.23 sys=0.00, real=0.19 secs] 5.054: [Full GC 5.054: [CMS (concurrent mode failure)[YG occupancy: 992483 K (1887488 K)]5.274: [weak refs processing, 0.0000130 secs]: 0K->0K(6291456K), 0.2347170 secs] 992483K->992483K(8178944K), [CMS Perm : 24058K->24058K(44408K)], 0.2348700 secs] [Times: user=0.28 sys=0.00, real=0.23 secs] 6.662: [Full GC 6.662: [CMS (concurrent mode failure)[YG occupancy: 1292895 K (1887488 K)]6.953: [weak refs processing, 0.0000140 secs]: 0K->0K(6291456K), 0.3063690 secs] 1292895K->1292895K(8178944K), [CMS Perm : 30692K->30692K(48120K)], 0.3065860 secs] [Times: user=0.66 sys=0.01, real=0.30 secs] After these 8 GCs, the GC log is much inline with what I'd expect, i.e. ParNew GCs, initial-marks, remarks, etc. In each of the above GCs: - young gen is increasing in occupancy - old gen remains empty - perm gen space size is expanding I can understand the Full GC being reported since perm gen is expanding, but I don't understand the reporting of "concurrent mode failure". Am I missing something? Is it possible HotSpot is reporting concurrent mode failure when perm gen is expanding? Here's the set of command line options in use: -Xmx8G -Xms8G -Xmn1500m -XX:+UseCompressedOops -XX:-UseGCOverheadLimit -XX:+UseConcMarkSweepGC -XX:MaxDirectMemorySize=5000m thanks, charlie ... PS: I didn't go look at / investigate OpenJDK HotSpot source code since this is JDK 6u21 and thought it might be possible something may have changed between 6u21 and what's in OpenJDK.

4 4

[RFR] 8016752: Test case for 8005857/8016740 (assert in GC_locker from PSOldGen::expand with -XX:+PrintGCDetails and Verbose)
by Andrey Zakharov 26 Nov '15

26 Nov '15

Hi, team. Here is simple test for JVM don't crash when its with PSOldGen, low memory and with -XX:+PrintGCDetails and -XX:+Verbose flags (https://bugs.openjdk.java.net/browse/JDK-8016740) based on Crasher attached to original incident bug webrev: http://cr.openjdk.java.net/~azakharov/8016752/webrev/ test bug: https://bugs.openjdk.java.net/browse/JDK-8016752 bug: https://bugs.openjdk.java.net/browse/JDK-8016740 https://bugs.openjdk.java.net/browse/JDK-8005857 Thanks.

4 14

RFR: 8057037: Verification in ClassLoaderData::is_alive is too slow
by Stefan Karlsson 08 Apr '15

08 Apr '15

Hi all, Please review this patch to remove some verification code that was added during the G1 Class Unloading project. The code was added to make sure we catch any class unloading bugs as early as possible. This verification code is run too often and is causing large GC times in our fastdebug test runs. In one of the tests I investigated, the Full GCs take 8 seconds with this verification and 0.2 seconds without it. Most of the verified pointers are already verified before and after GCs in ClassLoaderDataGraph::verify(). http://cr.openjdk.java.net/~stefank/8057037/webrev.00/ thanks, StefanK

5 6

Request for sponsor - JDK-8031538
by Staffan Friberg 03 Mar '15

03 Mar '15

Hi, I have created the a patch for JDK-8031538 - G1 eden usage is sometimes higher than target eden (printed Eden size) [1]. Since I'm not author I can't upload public WebRevs or request reviews, so I would like to ask if someone could sponsor this change and push it through the process. I have attached the small patch to this email. The patch make sure that the nursery target size calculation takes into account any regions that might currently be used for eden and not only the size of the survivor space. [1] - https://bugs.openjdk.java.net/browse/JDK-8031538 Cheers, Staffan Friberg

2 5

RFR: JDK-8061259: ParNew promotion failed is serialized on a lock
by Jungwoo Ha 16 Jan '15

16 Jan '15

Bug: https://bugs.openjdk.java.net/browse/JDK-8061259 hotspot code: http://cr.openjdk.java.net/~rasbold/8061259/webrev.00/ I created the patch for JDK9, but I can also observe this on JDK7 and 8. We are seeing several cases where GC worker threads are serialized on GCRareEvent_lock causing 2 digit seconds pause on moderate sized heap. I have a test code that can reproduce it and shows it is solved. import java.util.LinkedList; class PromoFail { static class Container { Container p; byte[] a; public Container(int size) { if (size > 0) { p = new Container(size / 2); } else { p = null; } a = new byte[size]; } } public static void main(String args[]) { if (args.length < 1) { System.err.println("@ 1st argument must be size in MB."); System.exit(1); } int size = 0; try { size = Integer.parseInt(args[0]) * 1024 * 1024; } catch (NumberFormatException e) { System.err.println("@ Cannot parse the size(=" + args[0] + ")"); System.exit(1); } // LinkedList will have more unbalanced workload. LinkedList<Container> list = new LinkedList<Container>(); // 1st iteration adds element without removal. // These are all live objects. for (int i = 0; i < size / 4; i++) { list.add(new Container(1)); } // Promote to the old gen. System.gc(); for (int containerSize = 2; container_size < 512; container_size *= 3) { for (int i = 0; i < size / 4; i++) { // Most likely removing an old object due to System.gc() from previous iteration. // This will cause fragmentation. list.remove(); list.add(new Container(containerSize)); } { System.gc(); Runtime runtime = Runtime.getRuntime(); System.out.println("@ Current Used: " + (runtime.totalMemory() - runtime.freeMemory()) / 1024 / 1024); } } } } You can run it with the following parameters. $ java -Xmx2g -Xms2g -Xmn1g -XX:+UseCMSFastPromotionFailure -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC -XX:ParallelGCThreads=6 PromoFail 4 Without UseCMSFastPromotionFailure #7: [GC (Allocation Failure) #7: [ParNew#6: [CMS-concurrent-abortable-preclean: 0.003/0.203 secs] [Times: user=0.20 sys=0.20 real=0.20 secs] (promotion failed): 838912K->943744K(943744K), 62.0419534 secs]#8: [CMS (concurrent mode failure): 1048441K->1048575K(1048576K), 1.7731336 secs] 1609551K->1170596K(1992320K), [Metaspace: 3547K->3547K(1056768K)], *63.8151607*secs] [Times: user=93.50 sys=22.12 real=63.82 secs] With UseCMSFastPromotionFailure #7: [GC (Allocation Failure) #7: [ParNew#6: [CMS-concurrent-abortable-preclean: 0.004/0.204 secs] [Times: user=0.30 sys=0.02 real=0.20 secs] (promotion failed): 838912K->943744K(943744K), 2.0949545 secs]#8: [CMS (concurrent mode failure): 1048363K->1048575K(1048576K), 1.7517250 secs] 1609551K->1170595K(1992320K), [Metaspace: 3546K->3546K(1056768K)], *3.8467384*secs] [Times: user=10.85 sys=1.04 real=3.85 secs] I also ran it on Dacapo benchmarks. Please see attached results. Those are subset of DaCapo that shows any promotion failed pause. You can see that some speed ups and no performance regressions.

4 38

RFR (smallish?) 8061611: Remove deprecated command line flags
by Derek White 16 Dec '14

16 Dec '14

Hi Team, First review request. Please let me know if I've forgotten something or have gone completely off the rails. The main point of this bug is to remove deprecated -XX options which are alias for other options. The only complicated part is that one case, /CMSParPromoteBlocksToClaim/ was not a true alias for /OldPLABSize/ but a parallel option with different defaults that were synchronized in ergo processing. This fix removes the /CMSParPromoteBlocksToClaim /variable but preserves using different defaults in the CMS case. Also in this fix I added warning messages to several remaining undocumented command line options aliases. This should ease removal of these options in the future CMSMarkStackSize ==> MarkStackSize (MarkStackSize not documented either, but came in jdk6) G1MarkStackSize ==> MarkStackSize CMSMarkStackSizeMax ==> MarkStackSizeMax (MarkStackSizeMax not documented either) ParallelMarkingThreads => ConcGCThreads (ConcGCThreads came in jdk6) ParallelCMSThreads ==> ConcGCThread Thanks, - Derek *Webrev*: http://cr.openjdk.java.net/~drwhite/8061611/webrev.00/ *Bug*: https://bugs.openjdk.java.net/browse/JDK-8061611 *Testing*: jprt: Saw 1-2 intermittent failures that went away on retesting - hangs and timeouts. refworkload: no differences jtreg: Saw a few unexplained results. Not sure if typical or not: Execution failed: `main' threw exception: java.lang.Exception: jmap -heap exited with error code: 1 * gc/metaspace/CompressedClassSpaceSizeInJmapHeap.java <http://oklahoma.us.oracle.com/net/bussund0416//export/users/drwhite/hs-gc-m…>: Checks that jmap -heap contains the flag CompressedClassSpaceSize Program `/export/users/drwhite/test-builds/j2sdk-image.11.17.2014/bin/java' interrupted! (timed out?) * closed/runtime/AppCDS/SharedArchiveConsistency.java <http://oklahoma.us.oracle.com/net/bussund0416//export/users/drwhite/hs-gc-m…>: SharedArchiveConsistency Plus a bunch of tests that are labelled "ignored".

4 13

RFR: 8064909: FragmentMetaspace.java got OutOfMemoryError
by Michail Chernov 08 Dec '14

08 Dec '14

Hi, Please review this simple fix for nightly test failure: Webrev: http://cr.openjdk.java.net/~eistepan/~mchernov/8064909/webrev.00/ Bug: https://bugs.openjdk.java.net/browse/JDK-8064909 Problem: test fails because of OOME (not enough heap size). Solution: heap size were increased. Testing: jtreg Thanks, Michail

4 12

Major GC occurring before CMS occupancy fraction
by nitin sharma 05 Dec '14

05 Dec '14

hi, I am facing the same issue.. We are using JDK 1.6. 0_23 and have set Occupancy Fraction to 80% but i can see CMS triggered at much below ration (around 53%).. is there a solution for same? I have used "-XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSInitiatingOccupancyOnly" option... complete JVM argument set ==> /usr/java/jdk1.6.0_23/bin/java -server -Xms16384m -Xmx16384m -XX:PermSize=512m -XX:MaxPermSize=1024m -XX:CompileThreshold=8000 -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+UseParNewGC -XX:MaxNewSize=6144m -XX:NewSize=6144m -XX:+UseConcMarkSweepGC -XX:ParallelGCThreads=4 -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSInitiatingOccupancyOnly -DUseSunHttpHandler=true -XX:+HeapDumpOnOutOfMemoryError Regards, Nitin Kumar Sharma.

3 5

Re: RFR: JDK-8055845 - Add trace event for promoted objects
by Erik Helin 02 Dec '14

02 Dec '14

(it seems like we lost hotspot-gc-dev(a)openjdk.java.net somewhere in this thread, I'm adding it back) On 2014-08-28 23:15, Staffan Friberg wrote: > Hi Erik, > > Thanks for the comments. >> - Aren't the events for promotion to the tenured generation (SerialOld) >> and the CMS generation missing? > The reason for leaving out these two, Serial completely and CMS > promotion, was due to that neither as far as I understand make use of > PLABs. I might be wrong here, but looking at the function TenuredGeneration::par_promote (in tenuredGeneration.cpp) it looks to me like SerialOld is using PLABs when ParNew is promoting objects from young to old. As for CMS, looking at ConcurrentMarkSweepGeneration::par_promote (in concurrentMarkSweepGeneration.cpp) it seems like each CMSParGCThreadState has a CFLS_LAB (CompactibleFreeListSpace Local Allocation Buffer) that is a thread-local allocation buffer. See compactibleFreeListSpace.{hpp,cpp} for more details. Given this, I think we should add events for Serial and CMS as well. On 2014-08-28 23:15, Staffan Friberg wrote: > So without a good sampling type of event it would end up being an > event for each aging and/or promotion that happened in the GC. As this > would be a very large number of events so I decided not to support those > cases due to performance concerns. If you have a good idea on how to > support it please let me know. I would see CMS as the priority of the > two, client workloads can usually be analyzed with a different collector > which might not be the case for a latency sensitive application. > >> - We try to keep the trace dependency (the header file) in >> gcTraceSend.cpp, see the pattern for all the other events in >> gcTrace.cpp (they all have a "report" and a "send" function). > Will update it to follow that pattern. Thanks! On 2014-08-28 23:15, Staffan Friberg wrote: >> - Would it make sense to differentiate, either by separate events or by >> a field in a event, between promotions to to-space and to the old >> generation? >> - The are two events for TLAB allocations, >> java/object_alloc_in_new_TLAB and java/object_alloc_outside_TLAB. >> What do you think about using two events for PLAB allocations as well: >> - java/object_alloc_in_new_PLAB >> - java/object_alloc_outside_PLAB > I think this is a matter of taste and probably how similar we want the > event to be to the existing allocation event. I personally prefer a > single event but if the GC team and serviceability team feel it would be > better to have two I can certainly rewrite. The reason for me preferring > a single event is just ease of analysis, you can easily filter a list of > events on a field, it is harder to merge two different events with > different fields and work with them in an straight forward fashion. > > Any general preference for having a single or multiple events? I would prefer to have two events in this case and try to follow the existing allocation events as much as possible (both in naming and in style). Keeping the tenured field (I missed it the first time I read the patch) is good. On 2014-08-28 23:15, Staffan Friberg wrote: >> - In PSPromotionManager, instead of utilizing the C++ friendship with >> PSScavenge, should we add a getter function for the gc_tracer? > Created a getter function. Thanks! If you make report_promotion_sample const, then the getter can return a const ParallelScavengeTracer*, right? Thanks, Erik > Will upload a new webrev shortly. > > //Staffan > > On 08/28/2014 02:27 AM, Erik Helin wrote: >> Hi Staffan, >> >> thanks for the patch, looks like a useful event! >> >> A few initial comments: >> - Aren't the events for promotion to the tenured generation (SerialOld) >> and the CMS generation missing? >> - We try to keep the trace dependency (the header file) in >> gcTraceSend.cpp, see the pattern for all the other events in >> gcTrace.cpp (they all have a "report" and a "send" function). >> - Would it make sense to differentiate, either by separate events or by >> a field in a event, between promotions to to-space and to the old >> generation? >> - The are two events for TLAB allocations, >> java/object_alloc_in_new_TLAB and java/object_alloc_outside_TLAB. >> What do you think about using two events for PLAB allocations as well: >> - java/object_alloc_in_new_PLAB >> - java/object_alloc_outside_PLAB >> - In PSPromotionManager, instead of utilizing the C++ friendship with >> PSScavenge, should we add a getter function for the gc_tracer? >> >> Thanks, >> Erik >> >> On 2014-08-27 16:28, Bengt Rutisson wrote: >>> >>> >>> Hi Staffan, >>> >>> Overall I think this change looks fine. I know that Erik Helin has some >>> thoughts on the naming of the events. I'll let him communicate those >>> thoughts. >>> >>> Apart from Erik's comments and the missing test case (that I know you >>> are working on) I think the change looks good. >>> >>> Thanks, >>> Bengt >>> >>> On 8/26/14 10:50 AM, Bengt Rutisson wrote: >>>> >>>> Hi all, >>>> >>>> Staffan sent me an updated webrev based on Erik's comments. I uploaded >>>> it here: >>>> http://cr.openjdk.java.net/~brutisso/8055845/webrev.01/ >>>> >>>> Thanks, >>>> Bengt >>>> >>>> >>>> On 2014-08-25 19:32, Staffan Friberg wrote: >>>>> Hi Erik, >>>>> >>>>> No issue with naming the field class, since the event is similar to >>>>> the Allocation event I used that as a starting point and it also uses >>>>> class as name together with a couple of other events. >>>>> >>>>> Will go through the descriptions and remove periods. >>>>> >>>>> Object age is basically the how many times an object has been kept in >>>>> survivor region, it is incremented each time a YC happens and the >>>>> object is aged. >>>>> Will see how I can update the description to make it clearer. Calling >>>>> the field tenuringAge might help? >>>>> >>>>>> From the documentation, >>>>>> http://docs.oracle.com/javase/8/docs/technotes/tools/unix/java.html >>>>>> >>>>>> -XX:MaxTenuringThreshold=/threshold/ >>>>>> >>>>>> Sets the maximum tenuring threshold for use in adaptive GC >>>>>> sizing. The largest value is 15. The default value is 15 for the >>>>>> parallel (throughput) collector, and 6 for the CMS collector. >>>>>> >>>>>> The following example shows how to set the maximum tenuring >>>>>> threshold to 10: >>>>>> >>>>>> -XX:MaxTenuringThreshold=10 >>>>>> >>>>>> >>>>>> -XX:+PrintTenuringDistribution >>>>>> >>>>>> Enables printing of tenuring age information. The following is >>>>>> an example of the output: >>>>>> >>>>>> Desired survivor size 48286924 bytes, new threshold 10 (max 10) >>>>>> - age 1: 28992024 bytes, 28992024 total >>>>>> - age 2: 1366864 bytes, 30358888 total >>>>>> - age 3: 1425912 bytes, 31784800 total >>>>>> ... >>>>>> >>>>>> Age 1 objects are the youngest survivors (they were created >>>>>> after the previous scavenge, survived the latest scavenge, and >>>>>> moved from eden to survivor space). Age 2 objects have survived >>>>>> two scavenges (during the second scavenge they were copied from >>>>>> one survivor space to the next). And so on. >>>>>> >>>>>> In the preceding example, 28 992 024 bytes survived one scavenge >>>>>> and were copied from eden to survivor space, 1 366 864 bytes are >>>>>> occupied by age 2 objects, etc. The third value in each row is >>>>>> the cumulative size of objects of age n or less. >>>>>> >>>>>> By default, this option is disabled. >>>>>> >>>>> >>>>> Thanks for the comments, >>>>> Staffan >>>>> >>>>> On 08/25/2014 09:55 AM, Erik Gahlin wrote: >>>>>> Did you manage to call the field "class"? It's a reserved word in >>>>>> C++, so we had to use "klass" in the past >>>>>> >>>>>> Descriptions with only one sentence shouldn't end with "." >>>>>> >>>>>> How is "Object Age" measured? >>>>>> >>>>>> As a user, I would expect the number to be in seconds/minutes/hours, >>>>>> but that is not the case. Perhaps an explanation in the description >>>>>> and/or a field name that better reflects what we really mean with >>>>>> age. >>>>>> >>>>>> Otherwise trace.xml looks good! >>>>>> >>>>>> Erik >>>>>> >>>>>> Staffan Friberg skrev 25/08/14 18:28: >>>>>>> Hi, >>>>>>> >>>>>>> Could I please get reviews for this RFE that adds a trace event for >>>>>>> aging and promotion for young collections in G1, CMS and Parallel >>>>>>> GC. >>>>>>> It works similarly to allocation events, and generates the event on >>>>>>> the slow path when either a direct copy occurs or a new PLAB is >>>>>>> request. >>>>>>> >>>>>>> Since I'm adding an event I cc:ed the serviceability list in case >>>>>>> anyone has any comments on the event and changes to trace.xml. >>>>>>> >>>>>>> RFE: https://bugs.openjdk.java.net/browse/JDK-8055845 >>>>>>> Webrev: http://cr.openjdk.java.net/~brutisso/8055845/webrev.00 >>>>>>> >>>>>>> Bengt has been kind and agreed to both sponsor and host the the >>>>>>> webrev. >>>>>>> >>>>>>> Thanks, >>>>>>> Staffan >>>>>>> >>>>>> >>>>> >>>> >>> >

5 17

RFR (S): 8066102: Clean up HeapRegionRemSet files
by Thomas Schatzl 02 Dec '14

02 Dec '14

Hi all, can I have reviews for this small cleanup? I went over heap region remembered set files recently and found dead code, useless code, tightened the public interface and tried to document the methods a little. I also moved FromCardCache accessor methods from OtherRegionTable to HeapRegionRemSet to do away with that needless indirection. Imo it fits better that way too. CR: https://bugs.openjdk.java.net/browse/JDK-8066102 Webrev: http://cr.openjdk.java.net/~tschatzl/8066102/webrev/ Testing: jprt Thanks, Thomas

4 6