December 2015 - 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

Re: Low-Overhead Heap Profiling
by Tony Printezis 04 Apr '17

04 Apr '17

Jeremy (and all), I’m not on the serviceability list so I won’t include the messages so far. :-) Also CCing the hotspot GC list, in case they have some feedback on this. Could I suggest a (much) simpler but at least as powerful and flexible way to do this? (This is something we’ve been meaning to do for a while now for TwitterJDK, the JDK we develop and deploy here at Twitter.) You can force allocations to go into the slow path periodically by artificially setting the TLAB top to a lower value. So, imagine a TLAB is 4M. You can set top to (bottom+1M). When an allocation thinks the TLAB is full (in this case, the first 1MB is full) it will call the allocation slow path. There, you can intercept it, sample the allocation (and, like in your case, you’ll also have the correct stack trace), notice that the TLAB is not actually full, extend its to top to, say, (bottom+2M), and you’re done. Advantages of this approach: * This is a much smaller, simpler, and self-contained change (no compiler changes necessary to maintain...). * When it’s off, the overhead is only one extra test at the slow path TLAB allocation (i.e., negligible; we do some sampling on TLABs in TwitterJDK using a similar mechanism and, when it’s off, I’ve observed no performance overhead). * (most importantly) You can turn this on and off, and adjust the sampling rate, dynamically. If you do the sampling based on JITed code, you’ll have to recompile all methods with allocation sites to turn the sampling on or off. (You can of course have it always on and just discard the output; it’d be nice not to have to do that though. IMHO, at least.) * You can also very cheaply turn this on and off (or adjust the sampling frequncy) per thread, if that’s be helpful in some way (just add the appropriate info on the thread’s TLAB). A few extra comments on the previous discussion: * "JFR samples per new TLAB allocation. It provides really very good picture and I haven't seen overhead more than 2” : When TLABs get very large, I don’t think sampling one object per TLAB is enough to get a good sample (IMHO, at least). It’s probably OK for something like jbb which mostly allocates instances of a handful of classes and has very few allocation sites. But, a lot of the code we run at Twitter is a lot more elaborate than that and, in our experience, sampling one object per TLAB is not enough. You can, of course, decrease the TLAB size to increase the sampling size. But it’d be good not to have to do that given a smaller TLAB size could increase contention across threads. * "Should it *just* take a stack trace, or should the behavior be configurable?” : I think we’d have to separate the allocation sampling mechanism from the consumption of the allocation samples. Once the sampling mechanism is in, different JVMs can take advantage of it in different ways. I assume that the Oracle folks would like at least a JFR event for every such sample. But in your build you can add extra code to collect the information in the way you have now. * Talking of JFR, it’s a bit unfortunate that the AllocObjectInNewTLAB event has both the new TLAB information and the allocation information. It would have been nice if that event was split into two, say NewTLAB and AllocObjectInTLAB, and we’d be able to fire the latter for each sample. * "Should the interval between samples be configurable?” : Totally. In fact, it’d be helpful if it was configurable dynamically. Imagine if a JVM starts misbehaving after 2-3 weeks of running. You can dynamically increase the sampling rate to get a better profile if the default is not giving fine-grain enough information. * "As long of these features don’t contribute to sampling bias” : If the sampling interval is fixed, sampling bias would be a very real concern. In the above example, I’d increment top by 1M (the sampling frequency) + p% (a fudge factor). * "Yes, a perhaps optional callbacks would be nice too.” : Oh, no. :-) But, as I said, we should definitely separate the sampling mechanism from the mechanism that consumes the samples. * "Another problem with our submitting things is that we can't really test on anything other than Linux.” : Another reason to go with a as platform independent solution as possible. :-) Regards, Tony ----- Tony Printezis | JVM/GC Engineer / VM Team | Twitter @TonyPrintezis tprintezis(a)twitter.com

7 31

PerfData counter: sun.gc.policy.generations in JDK 8
by Srinivas Ramakrishna 29 Apr '16

29 Apr '16

With perm gen going away (and being replaced by metaspace) in JDK 8, it makes sense that the counter sun.gc.policy.generations should be "2", rather than "3". However, in JDK 8 that counter still says 3. As I understand, the intention was that this counter would allow you to (for example) know the range of the sun.gc.generation.$num.* counters describing each of $num < sun.gc.policy.generations in the heap. Recall that the erstwhile perm gen in JDK 7 used to be synonymous with sun.gc.generation.2, but the JDK 8 avatars are now sun.gc.metaspace and sun.gc.compressedclassspace. The fix is simple, and I can submit a patch. Is there an existing bug for this? thanks! -- ramki

4 7

RFR (S): 8135200: Add White Box method that enumerates G1 old regions with less than specified liveness and collects statistics.
by Kirill Zhaldybin 13 Apr '16

13 Apr '16

Hi! Could you please review a patch for JDK-8135200? I added White Box method that enumerates G1 old regions with less than specified liveness and collects statistics. CR: https://bugs.openjdk.java.net/browse/JDK-8135200 Webrev: http://cr.openjdk.java.net/~kzhaldyb/webrevs/JDK-8135200/webrev.00/ hotspot: http://cr.openjdk.java.net/~kzhaldyb/webrevs/JDK-8135200/hotspot/webrev.00/ Thank you. Regards, Kirill

5 8

RFR(xs): 8134749: SoftReferences declared dead too early
by Per Liden 10 Mar '16

10 Mar '16

Hi, While preparing a different patch I looked through the ReferenceProcessor and noticed what looks like a silent mistreatment of SoftReferences. Summary: RefProcPhase1Task uses WorkerThread::id() to select the list to process. After the recent changes to how WorkGang works[1], this no longer guarantees that all reference lists are processed. This in turn means we might kill SoftReferences even when the policy says they should be kept alive. The fix here would be to use the worker_id (named "i" in this code) passed into the Task's work() function instead of using WorkerThread::id(). [1] There's no longer any guarantee that all GangWorker threads will execute the Task's work() function, since a quick-to-wakeup worker thread might steal the work intended for a slow-to-wakeup worker thread. Webrev: http://cr.openjdk.java.net/~pliden/8134749/webrev.0/ Bug: https://bugs.openjdk.java.net/browse/JDK-8134749 Testing: jprt Btw, I'll to send out a follow-up patch (JDK-8134744) which makes sure WorkerThread::id() and the worker_id always match to avoid this type of bugs in the future. /Per

3 7

RFR (XS): 8078673: Update TEST.groups for recent GC tests
by Derek White 01 Mar '16

01 Mar '16

Please review this simple for GC tests that require certain collectors (e.g. shouldn't run in embedded). Certain GC regression tests require specific collectors to be enabled in the JVM (by using -XX:+UseParallelGC, etc). But these tests were not listed in TEST.groups. This webrev adds the following tests to the appropriate needs_g1gc, needs_serialgc, needs_parallelgc, and needs_cmsgc lists. * gc/TestSmallHeap.java * gc/TestCardTablePageCommits.java * gc/arguments/TestParallelHeapSizeFlags.java gc/ergonomics/TestDynamicNumberOfGCThreads.java * gc/logging/TestGCId.java CR: https://bugs.openjdk.java.net/browse/JDK-8078673 Webrev: http://cr.openjdk.java.net/~drwhite/8078673/webrev.00/ Testing: JPRT Thanks, - Derek

7 21

RFR: JDK-8072725: Provide more granular levels for GC verification
by Poonam Bajaj Parhar 12 Feb '16

12 Feb '16

Hello, Please review these changes that split up the work done under Verify*GC options. This will be very useful in debugging GC issues/crashes where verifying the whole memory system with Verify*GC options slows down the process and makes it impossible to reproduce the problem. The changes introduce a new option /VerifySubSet///that can be used to specify the specific memory sub-systems that one wants to verify. It can be one or more of the sub-systems from these: threads, heap, symbol_table, string_table, codecache, dictionary, classloader_data_graph, metaspace, jni_handles, c-heap and codecache_oops. If nothing is specified with /VerifySubSet/ then whole of the memory system is verified with Verify*GC options. Bug:JDK-8072725: <https://bugs.openjdk.java.net/browse/JDK-8072725> Provide more granular levels for GC verification Webrev: http://cr.openjdk.java.net/~poonam/8072725/webrev.00/ Testing: JPRT, tested the changes with a simple test program. Thanks, Poonam

4 11

RFR: 8134963 [Newtests] New tests for G1 remembered set up and down
by Dmitry Fazunenko 27 Jan '16

27 Jan '16

Hi everyone, Can I have a couple of reviews for the new test for G1 Remembered Set: https://bugs.openjdk.java.net/browse/JDK-8134963 http://cr.openjdk.java.net/~dfazunen/8134963/ The test creates a lot of cross region references (making RSet to grow up) and then clear that references up. The test doesn't check any particular assertions, it just expects that there will be no crash. Thanks, Dima

3 11

RFR: 8141278: New tests for PLAB testing
by Michail Chernov 25 Jan '16

25 Jan '16

Hello, Could I have a couple of reviews for the new PLAB tests please? Bug: https://bugs.openjdk.java.net/browse/JDK-8141278 Webrev: http://cr.openjdk.java.net/~mchernov/8141278/webrev.00/ There are two new tests for PLAB. Test TestPLABNoResize checks how PLAB is used for promotion of objects. It starts the AppPLABFixedSize and inspects GC log details. The AppPLABFixedSize tries to fill specified amount of memory with small object, initiates young GC twice to promote objects from eden to survivor and then from survivor to old gen. TestPLABNoResize has different scenarios: 1. Promotion of small objects, which should be promoted using PLAB. 2. Promotion of big objects, which should be promoted by direct allocation. 3. Unreachable objects should not be promoted. Test TestPLABResize check behaviour of PLAB resizing. Test executes the AppPLABResize which tries to do next: 1. Performs some iterations of creating some fixed amount of objects and promoting them to survivor. Promotion of fixed amount of objects will cause to fixed desired PLAB size. 2. Performs some iterations - creates some amount of object, promotes it to survivor, decreases amount of objects. It causes to decreasing of desired PLAB size. 3. Performs next iterations which is similar to step 2, but increases amount of object to get increasing of desired PLAB size. Both tests use LogParser to get VM log information. Issues which were found by these tests: https://bugs.openjdk.java.net/browse/JDK-8140585 - PLAB statistics are flushed too late https://bugs.openjdk.java.net/browse/JDK-8141141 - Young and Old gen PLAB stats are similar in output with -XX:+PrintPLAB https://bugs.openjdk.java.net/browse/JDK-8139903 - G1EvacStats does not split log entries. Thanks, Michail

2 4

[PATCH] enhancement to ParallelScavenge Full GC
by ray alex 22 Jan '16

22 Jan '16

Hi all, Can I have reviews for the following enhancement? Description: The change addresses the inefficiency in the live_words_in_range() routine in ParallelScavenge Full GC, which generally costs most of the time during the compacting phase. Our idea records last query information of live_words_in_range as well as the query result. Our approach reuses last query result so that can reduce much computation of bitmap searching. Patch: as attached. Testing: Manual testing of full GC intensive applications including JOlden, Dacapo, SPECjvm2008 benchmarks. Results show that our enhancement can reduce much full GC time by 20~50%, depending on application scenarios. -- Lei Tianyang Institute of Parallel and Distributed System (IPADS) Shanghai Jiao Tong University

4 23