May 2013 - 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(S/M): 7132678: G1: verify that the marking bitmaps have no marks for objects over TAMS
by John Cuthbertson 29 Apr '14

29 Apr '14

Hi Everyone, Can I have a couple of volunteers review the changes for this CR? The webrev can be found at: http://cr.openjdk.java.net/~johnc/7132678/webrev.0/ Most of the changes come from a patch that Tony gave me before he left and I had to tweak them slightly to remove a spurious failure. The changes verify that the heap regions don't have any marks between [TAMS, top) at strategic places: start and end of each GC, start and end of remark and cleanup, and when allocating a region. Tony deserves the bulk of the credit so, if possible and there are no objections, I intend to list him as author of the change and include myself as a reviewer. Testing: GC test suite with the both the new flags (separately and together) and a low IHOP value. jprt with the new flags (+IgnoreUnrecognizedVMOptions so that product test runs did not fail). Thanks, JohnC

6 17

Request for review: 8010506 Typos and errors in gc-related flags in globals.hpp
by Tao Mao 09 Oct '13

09 Oct '13

8010506 Typos and errors in gc-related flags in globals.hpp https://jbs.oracle.com/bugs/browse/JDK-8010506 webrev: http://cr.openjdk.java.net/~tamao/8010506/webrev.00/ Changeset: NewRatio should defined as product(uintx, NewRatio, 2, \ "Ratio of old/new generation sizes") \ instead of product(uintx, NewRatio, 2, \ "Ratio of new/old generation sizes") \ PLUS other typos found by Jesper.

5 17

G1 question: concurrent cleaning of dirty cards
by Doerr, Martin 24 Sep '13

24 Sep '13

Hi all, we have a question about the interaction between G1 post barriers and the refinement thread's concurrent dirty card cleaning. The case in which the G1 post barrier sees a clean card is obviously not problematic, because it will add an entry in a dirty card queue. However, in case in which the Java thread (mutator thread) sees the card already dirtied, it won't enqueue the card again. Which is safe as long as its stored oop (1) is seen and processed (3') by the parallel refinement after having cleaned the card (1'): Java Thread (mutator) Refinement Thread (G1RemSet::concurrentRefineOneCard_impl calls oops_on_card_seq_iterate_careful) (1) store(oop) ( StoreLoad required here ?) (2) load(card==dirty) (1') store(card==clean) (2') StoreLoad barrier (3') load(oop) So the refinement thread seems to rely on getting the oop which was written BEFORE the (2) load(card==dirty) was observed. We wonder how this ordering is guaranteed? There are no StoreLoad barriers in the Java Thread's path. (StoreLoad ordering needs explicit barriers even on TSO platforms.) Kind regards, Martin

5 26

RFR (M/L): 8010722 assert: failed: heap size is too big for compressed oops (possibly CR 8009778)
by Thomas Schatzl 29 Aug '13

29 Aug '13

Hi all, can I have a review for the following change? In argument processing related to ergonomically determining compressed oops use, there were a few use-before-set issues leading to crashes that this fix tries to resolve. bugs.sun.com http://bugs.sun.com/view_bug.do?bug_id=8010722 JIRA: https://jbs.oracle.com/bugs/browse/JDK-8010722 webrev: http://cr.openjdk.java.net/~tschatzl/8010722/webrev/ testing: jprt, test cases Here's a walkthrough of the changes: As mentioned, the cause of this CR is that ergonomics for determining the maximum java heap size usable for compressed oops uses variables that are later changed ergonomically. It is best to look at the changes beginning from Arguments::set_ergonomics_flags(): the idea of this change is to avoid later overflow, so the change tries to conservatively estimate sizes of the non-java heap parts. The complication is that not even the later effective alignment of these heap parts has been determined at this point. So the change first calculates the maximum possible heap alignment by calling set_max_heap_alignment(); this size is influenced by OS page sizes, so the change needs to initialize large pages by calling os::large_page_init() in Arguments::parse(), before the call to set_ergonomics_flags(). The maximum possible alignment is then calculated by asking the active GC for its maximum alignment, as at this point the GC has already been determined, the maximum page size, and other requirements, like alignment for card table size etc. Now the code can calculate the conservative estimate for actual maximum heap for compressed oops used in set_use_compressed_oops(), by subtracting the conservatively aligned sizes of the other heap parts. (In Arguments::max_heap_for_compressed_oops()) The result is the maximum possible heap that can use compressed oops, minus the aligned metaspace size, minus the aligned null page size. There is another circular dependency problem here, the metaspace size itself is later ergonomically sized; the change fixes this problem by anticipating that in Arguments::max_heap_for_compressed_oops(), using the same predicate for determining whether to ergonomically size it or not [this is CR8009778 I think]. The other changes are straightforward: the os_* changes result from that large page initialization must be done earlier now; the changes in the collectors themselves are simply about providing the collector's maximum alignment. The change in Universe::reserve_heap() contains one assertion that checks whether the conservative estimate for alignment has been conservative enough earlier. The test case tests test cases from the CR that work now, and additional border cases related to ergonomically deciding heap size for compressed oops. One side effect of this change is that the ergonomically determined heap size is slighly smaller now (so that it always fits :). Thanks, Thomas

5 9

CMS parallel initial mark
by Hiroshi Yamauchi 28 Jun '13

28 Jun '13

Hi, I'd like to have the following contributed if it makes sense. 1) Here's a patch (against a recent revision of the hsx/hotspot-gc repo): http://cr.openjdk.java.net/~hiroshi/webrevs/cmsparinitmark/webrev.00/ that implements a parallel version of the initial mark phase of the CMS collector. It's relatively a straightforward parallelization of the existing single-threaded code. With the above patch, I see about ~3-6x speedup in the initial mark pause times. 2) Now, here's a related issue and a suggested fix/patch for it: I see that the initial mark and remark pause times sometimes spike with a large young generation. For example, under a 1 GB young gen / 3 GB heap setting, they occasionally spike up to ~500 milliseconds from the normal < 100 ms range, on my machine. As far as I can tell, this happens when the eden is fairly occupied (> 700 MB full) and not sufficiently divided up and the parallelism decreases (at the worst case it becomes almost single-threaded.) Here's a suggested patch in a separate patch: http://cr.openjdk.java.net/~hiroshi/webrevs/edenchunks/webrev.00/ that attempts to improve on this issue by implementing an alternative way of dividing up the eden into chunks for an increased parallelism (or better load balancing between the GC threads) for the young gen scan portion of the remark phase (and the now-parallelized initial mark phase.) It uses a CAS-based mechanism that samples the object boundaries in the eden space on the slow allocation code paths (eg. at the TLAB refill and large object allocation times) at all times. This approach is in contrast to the original mechanism that samples object boundaries in the eden space asynchronously during the preclean phase. I think the reason that the above issue happens is that when the young generation is large, a large portion of the eden space could get filled/allocated outside of the preclean phase (or a concurrent collection) and the object boundaries do not get sampled often/regularly enough. Also, it isn't very suited for the parallel initial mark because the initial mark phase isn't preceded by the preclean phase unlike the remark phase. According to the Dacapo benchmarks, this alternative sampling mechanism does not have noticeable runtime overhead despite it is engaged at all times. With this patch, I see that the (parallel) initial mark and remark pause times stay below 100 ms (no spikes) under the same setting. Both of these features/flags are disabled by default. You're welcome to handle the two patches separately. Thanks, Hiroshi

4 69

Re: RFR: 8013590: NPG: Add a memory pool MXBean for Metaspace
by Mikael Gerdin 26 Jun '13

26 Jun '13

(merging the gc-dev and svc-dev threads) Hi Erik, On 2013-05-29 10:44, Erik Helin wrote: > Hi all, > > this want sent to hotspot-gc-dev(a)openjdk.java.net, sending to > serviceability-dev(a)openjdk.java.net as well since the change is about > memory pools. > > This change adds two memory pools for metaspace, one for Metaspace and > one for compressed klass space. The memory pool for compressed klass > space will only have valus that differ from 0 or -1 (undefined) if > compressed klass pointers are used. > > Question: Should I use an empty pool when compressed klass pointers are > *not* used or should I just not expose the pool? > > This change also adds a manager for the pools: Metaspace Manager. > > I have also added a test that checks that the metaspace manager is > present and that the two pools are present. The test also verifies that > the compressed klass space pool act correct according to the > UseCompressedKlass flag. > > The last time I added metaspace memory pools, it triggered some > unforeseen bugs: > - Two asserts in jmm_GetMemoryUsage that asserted that a memory pool was > either of heap type or had an undefined init/max size. > - The jdk/test/java/lang/management/MemoryMXBean/MemoryTest.java failed > - The service lock was taken out of order with the metaspace locks > > These bugs have all been fixed: > - The asserts have been removed since they are no longer true > - The test has been updated but is not part of this change since it is a > JDK change > - This change does not make use of functions requiring the metaspace > lock. I had to remove some verification code in free_chunks_total to > ensure this. > > Webrev: > http://cr.openjdk.java.net/~ehelin/8013590/webrev.00/ Overall I think your fix looks good but I disagree with your choice of exposing an EmptyCompressedKlassSpacePool for the case of -UseCompressedClassPointers. Given the dynamic nature of the MemoryManagerMXBeans and MemoryPoolMXBeans it seems more true to the intentions of the API to ony expose a MemoryPool if it contains interesting information. Generally I don't think users of the management APIs can (or should) depend on the exact set of MemoryManagerMXBeans and MemoryPoolMXBeans available in a given VM instance. /Mikael > > Testing: > - One new jtreg test > - JPRT > - All the tests that failed in nighly testing last time now pass > > Thanks, > Erik >

3 5

URGENT: Request for review: 7122222: GC log is limited to 2G for 32-bit
by Tao Mao 06 Jun '13

06 Jun '13

7ux bug webrev: http://cr.openjdk.java.net/~tamao/7122222/webrev.00/ changeset: (1) make -D_FILE_OFFSET_BITS=64 only available to generating ostream.o Why conservative rather than making -D_FILE_OFFSET_BITS=64 globally applicable? Global setting of -D_FILE_OFFSET_BITS=64 on linux works fine; however, there are at least five code conflicts if introducing the flag globally to Solaris. One was resolved as in os_solaris.inline.hpp, but the rest four files had conflicts deep in c library. Even if they are excluded from setting -D_FILE_OFFSET_BITS=64, the compiled VM is corrupted. (2) For now, no Windows solution. I haven't found any clean solution for solving this problem on Windows. test: (1) Ability to write over 2g file for 32-bit builds were verified on the following configurations. Linux * i586 Solaris * i586 Solaris * sparc (2) Need a JPRT test for sanity check.

6 26

RFR(S): 8015237: Parallelize string table scanning during strong root processing
by John Cuthbertson 05 Jun '13

05 Jun '13

Hi Everyone, Can I have a couple of reviewers look over these changes - the webrev is: http://cr.openjdk.java.net/~johnc/8015237/webrev.0/ Summary: On some workloads we are seeing that the scan of the intern string table (among others) can sometimes take quite a while. This showed up on some FMW workloads with G1 where the scan of the string table dominated the pause time for some pauses. G1 was particularly affected since it doesn't do class unloading (and hence pruning of the string table) except at full GCs. The solution was to change the string table from being considered a single root task and treat similarly to the Java thread stacks: each GC worker claims a given number of buckets and scans the entries in those buckets. Testing Kitchensink; jprt; GC test suite. With all collectors. Overhead: Not real performance numbers but I did some measurement of the synchronization overhead of using 1 GC worker thread. They are summarized here: 0-threads (ms) 1-thread-chunked (ms) Min 0.200 0.300 Max 6.900 8.800 Avg 0.658 0.794 These were from 1 hour long runs of Kitchensink with around ~2800 GCs in each run. Thanks, JohnC

5 24

RFR (S/M): 8014078: G1: improve remembered set summary information by providing per region type information
by Thomas Schatzl 05 Jun '13

05 Jun '13

Hi all, could I get some reviews for the following change? It improves the remembered set summary information available with -XX: +G1SummarizeRSetStats by adding memory size and occupancy summaries broken down by region type (young, humonguous, free, other). Webrev: http://cr.openjdk.java.net/~tschatzl/8014078/webrev/ Note that this webrev is based on 8013895; I provided a full changeset including 8013895 at http://cr.openjdk.java.net/~tschatzl/8014078/webrev/8014078.8013895.diff JIRA: https://jbs.oracle.com/bugs/browse/JDK-8014078 bugs.sun.com: http://bugs.sun.com/view_bug.do?bug_id=8014078 Testing: jprt, jtreg tests About the change: - the output of G1SummarizeRSetStats now looks as follows (for dacapo/eclipse): After GC RS summary Concurrent RS processed 15299 cards Of 64 completed buffers: 64 (100.0%) by concurrent RS threads. 0 ( 0.0%) by mutator threads. Concurrent RS threads times (s) 0.06 Concurrent sampling threads times (s) 0.00 Total heap region rem set sizes = 512K. Max = 13K. >>>> 17K ( 3.4%) by 7 Young regions >>>> 7K ( 1.4%) by 3 Humonguous regions >>>> 157K ( 30.6%) by 64 Free regions >>>> 330K ( 64.6%) by 44 Other regions Static structures = 1K, free_lists = 254K. 277592 occupied cards represented. >>>> 0 ( 0.0%) entries by 7 Young regions >>>> 2 ( 0.0%) entries by 3 Humonguous regions >>>> 0 ( 0.0%) entries by 64 Free regions >>>> 277590 (100.0%) entries by 44 Other regions Max size region = 3:(O)[0x00000000f0900000,0x00000000f0a00000,0x00000000f0a00000], size = 14K, occupied = 25K. Did 0 coarsenings. Notice the breakdown of memory size and card occupancy by region type (marked with >>>> here). "Young" regions include all types of young regions (i.e. survivor) as survivor does not have a meaning for g1 outside of a gc. "Humonguous" and "Free" are self-explaining. "Other" regions include everything else. - added a new flag G1SummarizeRSetStatsTime that is used to control the time, i.e. before/after gc, when the periodicaly summaries are printed. This integer is treated as a bitset, where a set first bit indicates a request to print a summary after gc, the second bit a request to print a summary before gc. The alternative (which I'd like more) would be to change G1SummarizeRSetStats to act like this new flag to avoid introducing a new flag; however I'm hesitant to change this as G1SummarizeRSetStats is a publicly available flag (although diagnostic). - cleanup of the test cases: a large part of the code base for this CR reuses utility methods from 8013895, so I went ahead and factored out common code into a separate file that both the tests for 801385 and this CR use. Thanks, Thomas

4 8