January 2020 - hotspot-gc-dev

RFR: 8234440: ZGC: Print relocation information on info level
by Per Liden 22 Jan '20

22 Jan '20

When using -Xlog:gc*, I now and then find that I miss basic relocation information, since it's currently printed at the debug level on the relocation set selector. I think we should leave the current logging as is, since that's still useful when debugging the relocation set selector itself. However, I think we should propagate some of the high level information and print it on the info level. Here's an example of what the output looks like with this patch: [...] [68.926s][info][gc,reloc ] GC(6) Small Pages: 529 / 1058M(93%), Empty: 350M(31%), Compacting: 450M(40%)->20M(2%) [68.926s][info][gc,reloc ] GC(6) Medium Pages: 2 / 64M(6%), Empty: 0M(0%), Compacting: 64M(6%)->32M(3%) [68.926s][info][gc,reloc ] GC(6) Large Pages: 2 / 12M(1%), Empty: 6M(1%), Compacting: 0M(0%)->0M(0%) [68.926s][info][gc,reloc ] GC(6) Relocation: Successful [...] Bug: https://bugs.openjdk.java.net/browse/JDK-8234440 Webrev: http://cr.openjdk.java.net/~pliden/8234440/webrev.0 /Per

3 5

RFR (S) 8237586: Shenandoah: provide option to disable periodic GC
by Aleksey Shipilev 21 Jan '20

21 Jan '20

RFE: https://bugs.openjdk.java.net/browse/JDK-8237586 Webrev: https://cr.openjdk.java.net/~shade/8237586/webrev.01/ The VM option is unsigned, which leaves as with "0" as special value. It also matches the behavior of G1PeriodicGCInterval and GuaranteedSafepointInterval. Testing: hotspot_gc_shenandoah (includes new testcases) -- Thanks, -Aleksey

2 1

RFR (S) 8237570: Shenandoah: cleanup uses of allocation/free threshold in static heuristics
by Aleksey Shipilev 21 Jan '20

21 Jan '20

RFE: https://bugs.openjdk.java.net/browse/JDK-8237570 Fix: https://cr.openjdk.java.net/~shade/8237570/webrev.01/ As noted by Justinas in the separate thread, ShAllocThresh has no effect on "static" heuristics, so it should not be adjusted. Also, it should use ShMinFreeThresh, as other heuristics use. This makes ShFreeThresh unused, and it is removed for clarity. Testing: hotspot_gc_shenandoah -- Thanks, -Aleksey

2 1

RFR: 8237543: Shenandoah: More asserts around code roots
by Roman Kennke 20 Jan '20

20 Jan '20

We are still observing occasional corrupted code roots in Traversal GC. The assert always happens in code roots, and always at init-traversal. There are two ways this seems likely to happen: either when new code is generated, or during the previous GC cycle. We should plant some verifications there to ensure we fail earlier. Bug: https://bugs.openjdk.java.net/browse/JDK-8237543 Webrev: http://cr.openjdk.java.net/~rkennke/JDK-8237543/webrev/ Testing: hotspot_gc_shenandoah (fastdebug+release) ok Can I please get a review? Thanks, Roman

2 1

[14] RFR 8237396: JvmtiTagMap::weak_oops_do() should not trigger barriers
by Zhengyu Gu 20 Jan '20

20 Jan '20

Please review this small patch that avoids barriers in JvmtiTagMap::weak_oops_do() method. The method is used by GC and GC expects to see raw oops. Bug: https://bugs.openjdk.java.net/browse/JDK-8237396 Webrev: http://cr.openjdk.java.net/~zgu/JDK-8237396/webrev.00/ Test: hotspot_gc vmTestbase_nsk_jvmti (fastdebug and release) on x86_64 Linux Submit test in progress. Thanks, -Zhengyu

3 4

[14] RFR (XS): 8235305: Corrupted oops embedded in nmethods due to parallel modification during optional evacuation
by Thomas Schatzl 20 Jan '20

20 Jan '20

Hi all, can I get reviews for this change that fixes a bug in the abortable mixed gc algorithm where G1 might corrupt oops embedded in nmethods due to parallel modification during an optional evacuation phase? G1 currently collects embedded oops in nmethods twice: once in the optional roots list, and once as nmethods in the strong code roots list for a particular region. Now it can happen that this oop embedded in in the code stream is unaligned, so if that oop is modified during relocation word tearing may occur, causing follow-up crashes. The fix is to not collect oops from nmethods in the optional code root list as the strong code root list for a particular region already always contains it anyway. Thanks go to stefank, eriko and sjohanss for helping with analyzing, testing and the discussion around it. CR: https://bugs.openjdk.java.net/browse/JDK-8235305 Webrev: http://cr.openjdk.java.net/~tschatzl/8235305/webrev/ Testing: multiple runs of hs-tier1-5, multiple runs of the crashing application (24h kitchensink) with and without a VM modification and also with some G1 settings that caused crashes within 1-2 hours that reproduced the issue within 5 minutes. Currently starting perf test runs with and without this change: however since this change strictly reduces the work done at all times I am not expecting any regressions (and hence I am asking for review in advance). Thanks, Thomas

3 6

Discussion: improve humongous objects handling for G1
by Liang Mao 20 Jan '20

20 Jan '20

Hi Guys, We Alibaba have experienced the same problem as Man introduced. Some applications got frequent concurrent mark cycles and high cpu usage and even some to-space exhausted failures because of large amount of humongous object allocation even with G1HeapRegionSize=32m. But those applications worked fine with ParNew/CMS. We are working on some enhancements for better reclamation of humongous objects. Our first intention is to reduce the frequent concurrent cycles and possible to-space exhausted so the heap utility or arraylets are not taken into consideration yet. Our solution is more like a ParNew/CMS flow and will treat a humongous object as young or old. 1. Humongous object allocation in mutator will be considered into eden size and won't directly trigger concurrent mark cycle. That will avoid the possible to-space exhausted while concurrent mark is working and humongous allocations are "eating" the free regions. 2. Enhance the reclamation of short-live humongous object by covering object array that current eager reclaim only supports primitive type for now. This part looks same to JDK-8048180 and JDK-8073288 Thomas mentioned. The evacuation flow will iterate the humongous object array as a regular object if the humongous object is "young" which can be distinguished by the "age" field in markoop. The patch is being tested. We will share it once it proves to work fine with our applications. I don't know if any similar approach has been already tried and any advices? Thanks, Liang

2 1

Re: Abnormal high sys time in G1 GC
by Roy Zhang 20 Jan '20

20 Jan '20

Sent to hotspot-gc-dev mail list as well :) Thank you for ur help in advance!!! Thanks, Roy On Mon, Jan 20, 2020 at 6:22 PM Roy Zhang <roy.sunny.zhang007(a)gmail.com> wrote: > Dear JVM experts, > > Recently we found GC spike (long STW minor GC), and sys time is high when > we GC time is high. Normally sys time is near 0 seconds and minor GC is > less than 500ms. > > From > http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2017-October/020630.h… > and https://blog.gceasy.io/2016/12/11/sys-time-greater-than-user-time/, > high sys time could be caused by operation system problem/VM related > problem/memory constraint/disk IO pressure/Transparent Huge Pages. > > I checked them one by one, don't find any clue, could u please kindly > provide suggestion? Thanks in advance! > > 1.operation system problem > --We have enough CPU/memory/disk (48 cpu cores + 373 RAM with 160G heap, > disk is enough), and there is no error in /var/log/dmesg > 2. memory constraint > -- We have enough available memory. available memory (free -m) is 263G > 3. disk IO pressure > -- Not find issue from disk info from prometheus node exporter. > Granularity is 15s, and I can't find counterpart of avgqu-sz & util metrics > (disk IO util and saturation metrics) which is part of iostat. It could be > caused by big Granularity??? > 4. VM related problem > -- We are using physical machine > 5. Transparent Huge Pages. > It is madvise. It could be a problem, but we don't have this issue > previously. It has been running for nearly 20 weeks. > > *cat /sys/kernel/mm/transparent_hugepage/enabledalways [madvise] never* > > *JDK version:* > OpenJDK Runtime Environment, 1.8.0_222-b10 > > *Java Opts:* > -javaagent:/server/jmx_prometheus_javaagent-0.12.0.jar=xxxx:/server/config.yaml > > -server > -Dcom.sun.management.jmxremote > -Dcom.sun.management.jmxremote.port=xxxx > -Dcom.sun.management.jmxremote.rmi.port=xxxx > -Dcom.sun.management.jmxremote.local.only=false > -Dcom.sun.management.jmxremote.authenticate=false > -Dcom.sun.management.jmxremote.ssl=false > -Xloggc:/server/xxxx.log > -XX:+PrintGCDateStamps > -XX:AutoBoxCacheMax=1000000 > -XX:+UseG1GC > -XX:MaxGCPauseMillis=500 > -XX:+UnlockExperimentalVMOptions > -XX:G1NewSizePercent=50 > -XX:InitiatingHeapOccupancyPercent=70 > -XX:+ParallelRefProcEnabled > -XX:+ExplicitGCInvokesConcurrent > -XX:+UseStringDeduplication > -XX:+PrintGCDetails > -XX:+PrintGCTimeStamps > -Xms160g > -Xmx160g > -XX:+HeapDumpOnOutOfMemoryError > > *Snippet of GC log:* > > 2020-01-20T07:27:03.166+0000: 2756.665: [GC pause (G1 Evacuation Pause) > (young), *6.2899024 secs*] > [Parallel Time: 6255.0 ms, GC Workers: 33] > [GC Worker Start (ms): Min: 2756664.9, Avg: 2756665.5, Max: > 2756666.1, Diff: 1.2] > [Ext Root Scanning (ms): Min: 0.0, Avg: 0.5, Max: 5.3, Diff: 5.3, > Sum: 16.8] > [Update RS (ms): Min: 0.0, Avg: 0.8, Max: 1.1, Diff: 1.1, Sum: 25.6] > [Processed Buffers: Min: 0, Avg: 1.6, Max: 4, Diff: 4, Sum: 53] > [Scan RS (ms): Min: 142.0, Avg: 145.3, Max: 146.4, Diff: 4.4, Sum: > 4794.1] > [Code Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 3.5, Diff: 3.5, > Sum: 8.8] > * [Object Copy (ms): Min: 6100.1, Avg: 6101.8, Max: 6106.5, Diff: > 6.4, Sum: 201358.4]* > [Termination (ms): Min: 0.1, Avg: 5.2, Max: 6.7, Diff: 6.6, Sum: > 172.9] > [Termination Attempts: Min: 1, Avg: 1353.0, Max: 1476, Diff: > 1475, Sum: 44650] > [GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: > 7.0] > [GC Worker Total (ms): Min: 6253.4, Avg: 6254.1, Max: 6254.7, Diff: > 1.2, Sum: 206383.7] > [GC Worker End (ms): Min: 2762919.4, Avg: 2762919.6, Max: 2762919.8, > Diff: 0.4] > [Code Root Fixup: 0.6 ms] > [Code Root Purge: 0.0 ms] > [String Dedup Fixup: 0.7 ms, GC Workers: 33] > [Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4] > [Table Fixup (ms): Min: 0.0, Avg: 0.1, Max: 0.6, Diff: 0.6, Sum: 2.0] > [Clear CT: 4.0 ms] > [Other: 29.6 ms] > [Choose CSet: 0.1 ms] > [Ref Proc: 10.3 ms] > [Ref Enq: 0.6 ms] > [Redirty Cards: 11.3 ms] > [Humongous Register: 0.2 ms] > [Humongous Reclaim: 0.0 ms] > [Free CSet: 6.5 ms] > [Eden: 72576.0M(72576.0M)->0.0B(80896.0M) Survivors: 9344.0M->1024.0M > Heap: 83520.0M(160.0G)->11046.9M(160.0G)] > * [Times: user=27.19 sys=162.28, real=6.30 secs] * > > 2020-01-20T06:59:23.382+0000: 1096.881: [GC pause (G1 Evacuation Pause) > (young) (initial-mark), *4.1248088 secs*] > [Parallel Time: 4098.0 ms, GC Workers: 33] > [GC Worker Start (ms): Min: 1096882.1, Avg: 1096882.8, Max: > 1096883.2, Diff: 1.2] > [Ext Root Scanning (ms): Min: 4.0, Avg: 4.8, Max: 6.1, Diff: 2.0, > Sum: 159.7] > [Update RS (ms): Min: 0.0, Avg: 0.3, Max: 1.1, Diff: 1.1, Sum: 9.5] > [Processed Buffers: Min: 0, Avg: 1.3, Max: 6, Diff: 6, Sum: 43] > * [Scan RS (ms): Min: 2001.2, Avg: 2012.2, Max: 2013.4, Diff: 12.2, > Sum: 66401.0]* > [Code Root Scanning (ms): Min: 0.0, Avg: 0.6, Max: 10.7, Diff: 10.7, > Sum: 18.5] > * [Object Copy (ms): Min: 2039.3, Avg: 2049.2, Max: 2079.5, Diff: > 40.2, Sum: 67623.1]* > [Termination (ms): Min: 0.0, Avg: 29.6, Max: 39.7, Diff: 39.7, Sum: > 978.0] > [Termination Attempts: Min: 1, Avg: 6587.0, Max: 8068, Diff: > 8067, Sum: 217372] > [GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.4, Sum: > 7.9] > [GC Worker Total (ms): Min: 4096.3, Avg: 4096.9, Max: 4097.7, Diff: > 1.4, Sum: 135197.8] > [GC Worker End (ms): Min: 1100979.5, Avg: 1100979.7, Max: 1100979.9, > Diff: 0.4] > [Code Root Fixup: 0.6 ms] > [Code Root Purge: 0.2 ms] > [String Dedup Fixup: 1.0 ms, GC Workers: 33] > [Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] > [Table Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.7, Diff: 0.7, Sum: 1.4] > [Clear CT: 3.4 ms] > [Other: 21.7 ms] > [Choose CSet: 0.0 ms] > [Ref Proc: 9.1 ms] > [Ref Enq: 0.9 ms] > [Redirty Cards: 4.3 ms] > [Humongous Register: 0.2 ms] > [Humongous Reclaim: 0.0 ms] > [Free CSet: 5.3 ms] > [Eden: 81184.0M(81184.0M)->0.0B(72576.0M) Survivors: 736.0M->9344.0M > Heap: 83508.0M(160.0G)->10944.0M(160.0G)] > > * [Times: user=68.40 sys=9.11, real=4.13 secs] * > > Thanks, > Roy >

1 0

Discussion: improve humongous objects handling for G1
by Man Cao 20 Jan '20

20 Jan '20

Hi all, While migrating our workload from CMS to G1, we found many production applications suffer from humongous allocations. The default threshold for humongous objects is often too small for our applications with heap sizes between 2GB-15GB. Humongous allocations caused noticeable increase in the frequency of concurrent old-gen collections, mixed collections and CPU usage. We could advise applications to increase G1HeapRegionSize. But some applications still suffer with G1HeapRegionSize=32M. We could also advise applications to refactor code to break down large objects. But it is a high cost effort that may not always be feasible. We'd like to work with the OpenJDK community together to improve G1's handling of humongous objects. Thomas Schatzl mentioned to me a few efforts/ideas on this front in an offline chat: a. Allocation into tail regions of humongous object: JDK-8172713, JDK-8031381 b. Commit additional virtual address space for humongous objects. c. Improve the region selection heuristics (e.g., first-fit, best-fit) for humongous objects. I didn't find open CRs for b. and c. Could someone give pointers? Are there any other ideas/prototypes on this front? -Man

3 5

RFR (M): 8235860: Obsolete the UseParallelOldGC option
by Thomas Schatzl 17 Jan '20

17 Jan '20

Hi all, can I get reviews for this change that implements obsoletion of the UseParallelOldGC option, i.e. removal of the Parallel GC Serial Old collector? ((I am counting this as "M" because it's 99% removal of code) CR: https://bugs.openjdk.java.net/browse/JDK-8235860 Webrev: http://cr.openjdk.java.net/~tschatzl/8235860/webrev/ Testing: hs-tier1-5 almost done Thanks, Thomas

3 8