December 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

[8u-hs-dev] Backport RFR: 7176220: 'Full GC' events miss date stamp information occasionally
by Andreas Eriksson 02 Mar '15

02 Mar '15

Hi, This backport of JDK-7176220 <https://bugs.openjdk.java.net/browse/JDK-7176220> imported cleanly from the jdk9 changeset: http://hg.openjdk.java.net/jdk9/hs-gc/hotspot/rev/93b6fb9abdb4 For more information, please see the jdk9 review thread: http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2014-November/011314.… Regards, Andreas

3 8

RFR (S): 8066566: Refactor ParNewGeneration to contain ParNewTracer
by Marcus Larsson 09 Feb '15

09 Feb '15

Hi, I would like reviews for the following small patch. Like the bug description says, the ParNewTracer is stack-allocated during ParNewGeneration::collect(), forcing us to send the tracer as an argument to functions that might need it. This patch moves the tracer, and makes it a field in ParNewGeneration instead. The change includes adding a getter for this field, even though it is not used, however, future changes adding PLAB tracing [1] will require this. Webrev: http://cr.openjdk.java.net/~mlarsson/8066566/webrev.00/ Bug: https://bugs.openjdk.java.net/browse/JDK-8066566 Testing: jprt Thanks, Marcus [1]: https://bugs.openjdk.java.net/browse/JDK-8055845

3 11

RFR: 8066771: Refactor VM GC operations caused by allocation failure
by Marcus Larsson 06 Feb '15

06 Feb '15

Hi, I would like reviews for the following patch, cleaning up and refactoring VM GC operations for failed allocations. Summary: Different GCs have specialized VM_GC_Operations for collecting due to allocation failure. Part of this code is duplicated. The patch adds a VM_CollectForAllocation class that removes this duplicated code and handles the allocation size and result for such operations. It also serves as a common base where tracing can easily be added for these operations, regardless of which GC is used. In addition to the above refactoring, the patch also cleans up around the VM GC operations. These changes include: * Indentation and whitespace fixes * Change 'unsigned int' to 'uint' * Change some ints to uint, where it makes more sense (gclocker_stalled_count for example) Webrev: http://cr.openjdk.java.net/~mlarsson/8066771/webrev.00/ Bug: https://bugs.openjdk.java.net/browse/JDK-8066771 Testing: jprt, local jtreg (test/gc) Thanks, Marcus

3 9

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: 8066122: CollectionUsageThreshold.java times out when run with -XX:+ExplicitGCInvokesConcurrent
by Michail Chernov 13 Jan '15

13 Jan '15

Hi, Please review small fix for: https://bugs.openjdk.java.net/browse/JDK-8066122 Webrev: http://cr.openjdk.java.net/~eistepan/~mchernov/8066122/webrev.00/ Summary: CollectionUsageThreshold.java hangs due to VM performs concurrent GC with -XX:+ExplicitGCInvokesConcurrent flag, as result - notification is not received. Excluded test execution with -XX:+ExplicitGCInvokesConcurrent. Thanks, Michail

4 11

Removing G1 Reference Post Write Barrier StoreLoad Barrier
by Erik Österlund 09 Jan '15

09 Jan '15

Hi all, The StoreLoad barrier in G1’s reference post write barrier is stinging in my eyes so I sat down today and tried to figure out how to remove it and think I found a solution. Thought I’d share my thoughts here and see if I have understood the problem or if I’m missing something. The wanted invariant is that the post-barrier happens, well yeah after the reference write (duhh… deep insight I know). However, even TSO architectures allow the use of store buffers and hence enforce the use of painful StoreLoad fences. So abstracting away some unimportant things in the barrier (like SATB, young gen check, cross region check etc), the wanted control flow for the write barrier is: T1: write reference T1: load card, check if dirty, if so skip ahead So my understanding of the problem is that due to aforementioned reasons, these two operations are allowed to re-order due to the reference write being stuck for a while in the store buffer. The current solution is to emit an expensive StoreLoad fence before the loading the card to check if it is dirty. Without that fence and other precautions, this possible ordering could happen: __ card is visibly dirty __ Step 1. T1 (mutator): load card -> is dirty, skip rest of barrier Step 2. T2 (conc refinement): clean and process card with the old reference globally visible at this point Step 3. T1 (mutator): write ref (lazy serialization due to store buffer) <— reference write is forgotten As we can see, in step 3 the mutator reference write is unfortunately forgotten due to the reference write staying in the store buffer until after the card has been processed by the concurrent refinement thread. The good news is that this race can be solved with asymmetric dekker synchronization, which comes in different flavours. The idea is to allow the reference write and card load to be reordered, as long as they both happen before references are processed by the concurrent refinement thread. We achieve this by moving the synchronization overheads to the concurrent refinement thread instead of the mutator post write barrier. To do this we introduce a new operation, here called rendezvous, which will make sure that remote CPU store buffers have been drained. Given the existence of this operation, card refinement could be rewritten into this form: 1. *card = clean 2. storeload <— guarantee local store buffer is drained so mutators see the card is clean 3. rendezvous <— guarantee remote store buffer is drained so their reference writes are visible, even in case of the unfortunate reordering 4. process card Or in an amortised form: 1. for all cards in buffer, clean 2. storeload 3. rendezvous 4. for all cards in buffer, process card The rendezvous will prevent the unfortunate race in the previous example by making sure both step 1 and 3 happen before step 2 in total order. Now of course, this brings us to the question of how to implement the rendezvous operation. Windows has a neat system call, FlushProcessWriteBuffers, which will do exactly what we need using IPI. AFAIK it’s also required of calls to mprotect to flush the store buffers of remote CPUs in a similar fashion which could be used in UNIX systems. Or one could simply wait long enough for the ~32ish store buffer entries have for sure been serialized. Or put one thread on each CPU (using affinity) and make a handshake with them using a condition variable - the context switch should already serialize the store buffer. If I have not misunderstood the problem, it would be nice to get rid of the evil StoreLoad fence, and I could volunteer to provide a fix, but I would need some help to do performance regression and testing. The idea relies on moving the synchronization costs to the concurrent refinement threads and amortise those synchronization costs away by batching card refinement. Thanks, /Erik

3 9