High Reference Processing/Object Copy time

[Bernd Eckenfels]

The sys time is very high in this snippet, how to the other snippets compare? Did you turn off transparent huge pages (THP) in your OS and is there no swapping happening?

BTW: this is more a discussion for the user mailing list.

Gruss
Bernd
--
http://bernd.eckenfels.net
________________________________
From: hotspot-gc-dev <hotspot-gc-dev-bounces at openjdk.java.net> on behalf of Sundara Mohan M <email.sundarms at gmail.com>
Sent: Thursday, July 13, 2017 4:11:41 AM
To: hotspot-gc-dev at openjdk.java.net
Subject: High Reference Processing/Object Copy time

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/20170713/851c2762/attachment.htm>