High Reference Processing/Object Copy time

[Sundara Mohan M]

Hi,
   I am observing a odd behaviour (very high ref proc time once) with G1GC

gc log snippet,

flags used
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)
Memory: 4k page, physical 132290100k(1065596k free), swap
132120572k(131992000k free)
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


....
2017-07-12T17:02:40.227+0000: 77743.943: [GC pause (G1 Evacuation Pause)
(young)
Desired survivor size 104857600 bytes, new threshold 2 (max 15)
- age   1:   38456192 bytes,   38456192 total
- age   2:   86746408 bytes,  125202600 total
 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
0.00 ms]
 77743.943: [G1Ergonomics (CSet Construction) add young regions to CSet,
eden: 174 regions, survivors: 24 regions, predicted young region time:
1277.98 ms]
 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
e time: 500.00 ms]
 77751.132: [G1Ergonomics (Concurrent Cycles) request concurrent cycle
initiation, reason: occupancy higher than threshold, occupancy: 21147680768
bytes, allocation reques
t: 0 bytes, threshold: 14978698425 bytes (45.00 %), source: end of GC]
, 7.1891696 secs]
   [Parallel Time: 2253.1 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 77743943.2, Avg: 77743943.3, Max:
77743943.4, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 1.7, Avg: 3.5, Max: 6.5, Diff: 4.8,
Sum: 44.9]
      [Update RS (ms): Min: 39.2, Avg: 42.4, Max: 45.1, Diff: 5.9, Sum:
551.8]
         [Processed Buffers: Min: 26, Avg: 57.4, Max: 78, Diff: 52, Sum:
746]
      [Scan RS (ms): Min: 1.8, Avg: 3.7, Max: 4.5, Diff: 2.7, Sum: 47.5]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0,
Sum: 0.0]
*      [Object Copy (ms): Min: 2198.1, Avg: 2198.7, Max: 2202.7, Diff: 4.6,
Sum: 28583.3]*
      [Termination (ms): Min: 0.0, Avg: 4.5, Max: 4.9, Diff: 4.9, Sum: 58.4]
         [Termination Attempts: Min: 1, Avg: 16.7, Max: 28, Diff: 27, Sum:
217]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
0.4]
      [GC Worker Total (ms): Min: 2252.7, Avg: 2252.8, Max: 2252.9, Diff:
0.2, Sum: 29286.3]
      [GC Worker End (ms): Min: 77746196.1, Avg: 77746196.1, Max:
77746196.1, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [String Dedup Fixup: 167.7 ms, GC Workers: 13]
      [Queue Fixup (ms): Min: 0.0, Avg: 0.4, Max: 1.2, Diff: 1.2, Sum: 5.1]
      [Table Fixup (ms): Min: 165.5, Avg: 165.9, Max: 166.3, Diff: 0.9,
Sum: 2156.9]
   [Clear CT: 1.5 ms]
   [Other: 4766.8 ms]
      [Choose CSet: 0.0 ms]
*      [Ref Proc: 4763.9 ms]*
      [Ref Enq: 0.8 ms]
      [Redirty Cards: 0.7 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.4 ms]
*   [Eden: 1392.0M(1392.0M)->0.0B(1440.0M) Survivors: 192.0M->144.0M Heap:
20.8G(31.0G)->19.6G(31.0G)]*
* [Times: user=22.82 sys=13.83, real=7.19 secs]*

*Question*
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.
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.
3. Why is this happening occasionally and is there a way to enable more
logs when this happens.


Thanks,
Sundar
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20170712/6b9399a8/attachment.htm>