Hello, Can you say a bit what's the actual problem? Your smys times in those GCs look large, but it's only a 4s Pause for a 160gb heap. I am sure you saw that pause time before? I think it's pretty hard to tell after the fact, but with such a large system I would lean towards problems outside of the JVM.
Gruss Bernd -- http://bernd.eckenfels.net ________________________________ Von: hotspot-gc-use <hotspot-gc-use-boun...@openjdk.java.net> im Auftrag von Roy Zhang <roy.sunny.zhang...@gmail.com> Gesendet: Monday, January 20, 2020 11:22:43 AM An: hotspot-gc-use@openjdk.java.net <hotspot-gc-use@openjdk.java.net> Betreff: Abnormal high sys time in G1 GC 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.html >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/enabled always [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
_______________________________________________ hotspot-gc-use mailing list hotspot-gc-use@openjdk.java.net https://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
