<div dir="ltr">Hi,<div>   I am observing a odd behaviour (very high ref proc time once) with G1GC</div><div><br></div><div>gc log snippet,</div><div><br></div><div>flags used</div><div><div>Java HotSpot(TM) 64-Bit Server VM (25.112-b15) for linux-amd64 JRE (1.8.0_112-b15), built on Sep 22 2016 21:10:53 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)</div><div>Memory: 4k page, physical 132290100k(1065596k free), swap 132120572k(131992000k free)</div><div>CommandLine flags: -XX:G1MaxNewSizePercent=30 -XX:G1OldCSetRegionThresholdPercent=20 -XX:GCLogFileSize=20971520 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=out-of-memory-heap-dump -XX:InitialHeapSize=33285996544 -XX:MaxGCPauseMillis=500 -XX:MaxHeapSize=33285996544 -XX:MetaspaceSize=536870912 -XX:NumberOfGCLogFiles=20 -XX:+ParallelRefProcEnabled -XX:+PrintAdaptiveSizePolicy -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:+UnlockExperimentalVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:+UseGCLogFileRotation -XX:+UseStringDeduplication</div></div><div><br></div><div><br></div><div>....</div><div><div>2017-07-12T17:02:40.227+0000: 77743.943: [GC pause (G1 Evacuation Pause) (young)</div><div>Desired survivor size 104857600 bytes, new threshold 2 (max 15)</div><div>- age   1:   38456192 bytes,   38456192 total</div><div>- age   2:   86746408 bytes,  125202600 total</div><div> 77743.943: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 149039, predicted base time: 374.57 ms, remaining time: 125.43 ms, target pause time: 50</div><div>0.00 ms]</div><div> 77743.943: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 174 regions, survivors: 24 regions, predicted young region time: 1277.98 ms]</div><div> 77743.943: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 174 regions, survivors: 24 regions, old: 0 regions, predicted pause time: 1652.55 ms, target paus</div><div>e time: 500.00 ms]</div><div> 77751.132: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: occupancy higher than threshold, occupancy: 21147680768 bytes, allocation reques</div><div>t: 0 bytes, threshold: 14978698425 bytes (45.00 %), source: end of GC]</div><div>, 7.1891696 secs]</div><div>   [Parallel Time: 2253.1 ms, GC Workers: 13]</div><div>      [GC Worker Start (ms): Min: 77743943.2, Avg: 77743943.3, Max: 77743943.4, Diff: 0.2]</div><div>      [Ext Root Scanning (ms): Min: 1.7, Avg: 3.5, Max: 6.5, Diff: 4.8, Sum: 44.9]</div><div>      [Update RS (ms): Min: 39.2, Avg: 42.4, Max: 45.1, Diff: 5.9, Sum: 551.8]</div><div>         [Processed Buffers: Min: 26, Avg: 57.4, Max: 78, Diff: 52, Sum: 746]</div><div>      [Scan RS (ms): Min: 1.8, Avg: 3.7, Max: 4.5, Diff: 2.7, Sum: 47.5]</div><div>      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]</div><div><b>      [Object Copy (ms): Min: 2198.1, Avg: 2198.7, Max: 2202.7, Diff: 4.6, Sum: 28583.3]</b></div><div>      [Termination (ms): Min: 0.0, Avg: 4.5, Max: 4.9, Diff: 4.9, Sum: 58.4]</div><div>         [Termination Attempts: Min: 1, Avg: 16.7, Max: 28, Diff: 27, Sum: 217]</div><div>      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.4]</div><div>      [GC Worker Total (ms): Min: 2252.7, Avg: 2252.8, Max: 2252.9, Diff: 0.2, Sum: 29286.3]</div><div>      [GC Worker End (ms): Min: 77746196.1, Avg: 77746196.1, Max: 77746196.1, Diff: 0.0]</div><div>   [Code Root Fixup: 0.1 ms]</div><div>   [Code Root Purge: 0.0 ms]</div><div>   [String Dedup Fixup: 167.7 ms, GC Workers: 13]</div><div>      [Queue Fixup (ms): Min: 0.0, Avg: 0.4, Max: 1.2, Diff: 1.2, Sum: 5.1]</div><div>      [Table Fixup (ms): Min: 165.5, Avg: 165.9, Max: 166.3, Diff: 0.9, Sum: 2156.9]</div><div>   [Clear CT: 1.5 ms]</div><div>   [Other: 4766.8 ms]</div><div>      [Choose CSet: 0.0 ms]</div><div><b>      [Ref Proc: 4763.9 ms]</b></div><div>      [Ref Enq: 0.8 ms]</div><div>      [Redirty Cards: 0.7 ms]</div><div>      [Humongous Register: 0.2 ms]</div><div>      [Humongous Reclaim: 0.1 ms]</div><div>      [Free CSet: 0.4 ms]</div><div><b>   [Eden: 1392.0M(1392.0M)->0.0B(1440.0M) Survivors: 192.0M->144.0M Heap: 20.8G(31.0G)->19.6G(31.0G)]</b></div><div><b> [Times: user=22.82 sys=13.83, real=7.19 secs]</b></div></div><div><b><br></b></div><div><b>Question</b></div><div>1. Is there a way to find out why Ref Proc took 4.7 s at this instance only? all other instances it was less than a second.</div><div>2. Why object copy took 2.1s even though young gen region size is 1.3G in this case and there was not much garbage collected in this case.</div><div>3. Why is this happening occasionally and is there a way to enable more logs when this happens.</div><div><br></div><div><br></div><div>Thanks,</div><div>Sundar</div></div>