JDK-8040120 : Long delays during GC pause in G1 in some situations
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 9
  • Priority: P4
  • Status: Open
  • Resolution: Unresolved
  • Submitted: 2014-04-14
  • Updated: 2019-02-11
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
Other
tbdUnresolved
Related Reports
Relates :  
JDK-8057000 - Increase parallelism in String deduplication fixup
Relates :  
JDK-8029361 - Stress bpm sq:performance is slow with g1gc - not freeing regions correctly
Description
In some cases (possibly high load machines) starting up the worker threads to process a gang task takes a lot of time.

Eg. Stress BPM or CRM Fuse

   [Parallel Time: 420.8 ms, GC Workers: 8]
      [GC Worker Start (ms):  1178165.2  1178377.4  1178457.8  1178572.3  1178572.6  1178572.9  1178573.2  1178573.4
       Min: 1178165.2, Avg: 1178483.1, Max: 1178573.4, Diff: 408.1]
      [Ext Root Scanning (ms):  44.4  0.1  0.1  0.1  0.1  0.1  0.0  0.0
       Min: 0.0, Avg: 5.6, Max: 44.4, Diff: 44.3, Sum: 44.9]
         [SH_PS_Universe_oops_do:  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [SH_PS_JNIHandles_oops_do:  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [SH_PS_ObjectSynchronizer_oops_do:  0.3  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.3, Diff: 0.3, Sum: 0.3]
         [SH_PS_FlatProfiler_oops_do:  0.1  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
         [SH_PS_Management_oops_do:  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [SH_PS_SystemDictionary_oops_do:  0.1  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
         [SH_PS_ClassLoaderDataGraph_oops_do:  8.9  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 1.1, Max: 8.9, Diff: 8.9, Sum: 8.9]
         [SH_PS_jvmti_oops_do:  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [SH_PS_CodeCache_oops_do:  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [SH_PS_Threads_oops_do:  12.0  0.1  0.1  0.1  0.1  0.0  0.0  0.0
          Min: 0.0, Avg: 1.5, Max: 12.0, Diff: 12.0, Sum: 12.3]
         [SH_PS_StringTable_oops_do:  34.4  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 4.3, Max: 34.4, Diff: 34.4, Sum: 34.4]
         [G1H_PS_filter_satb_buffers:  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [G1H_PS_refProcessor_oops_do:  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Update RS (ms):  284.5  26.7  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 38.9, Max: 284.5, Diff: 284.5, Sum: 311.2]
         [Processed Buffers:  260  188  0  0  0  0  0  0
          Min: 0, Avg: 56.0, Max: 260, Diff: 260, Sum: 448]
      [Scan RS (ms):  0.1  4.9  0.1  0.1  0.1  0.0  0.0  0.0
       Min: 0.0, Avg: 0.7, Max: 4.9, Diff: 4.9, Sum: 5.5]
      [Code Root Scanning (ms):  0.0  0.7  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.1, Max: 0.7, Diff: 0.7, Sum: 0.7]
      [Object Copy (ms):  77.9  161.7  113.3  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 44.1, Max: 161.7, Diff: 161.7, Sum: 353.0]
      [Termination (ms):  3.7  7.4  14.2  8.6  6.2  5.9  5.7  0.0
       Min: 0.0, Avg: 6.5, Max: 14.2, Diff: 14.2, Sum: 51.7]
         [Termination Attempts:  1  456  485  1  1  1  1  1
          Min: 1, Avg: 118.4, Max: 485, Diff: 484, Sum: 947]
      [GC Worker Other (ms):  0.0  0.0  0.1  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.3]
      [GC Worker Total (ms):  410.6  201.5  127.8  8.9  6.4  6.1  5.9  0.1
       Min: 0.1, Avg: 95.9, Max: 410.6, Diff: 410.5, Sum: 767.3]
      [GC Worker End (ms):  1178575.8  1178579.0  1178585.5  1178581.1  1178579.0  1178579.0  1178579.0  1178573.5
       Min: 1178573.5, Avg: 1178579.0, Max: 1178585.5, Diff: 12.0]
   [Code Root Fixup: 1.8 ms]
   [Code Root Migration: 0.1 ms]
   [Clear CT: 0.8 ms]
   [Other: 283.0 ms]
      [Choose CSet: 0.1 ms]
      [Ref Proc: 278.8 ms]
      [Ref Enq: 0.2 ms]
      [Card Redirty: 0.6 ms]
      [Humongous Reclaim: 1.4 ms]
      [Free CSet: 0.8 ms]
         [Young Free CSet: 0.8 ms]
         [Nonyoung Free CSet: 0.0 ms]
   [Eden: 547.0M(547.0M)->0.0B(549.0M) Survivors: 53.0M->51.0M Heap: 2433.2M(3072.0M)->1898.7M(3072.0M)]
 [Times: user=1.10 sys=0.01, real=0.71 secs]

As shown in above log snippet, this delay of the worker threads causes many of the threads contribute absolutely nothing to the pause time.

Also, in this case (stress bpm), parallel reference processing is enabled - without it, reference processing does not take any time at all while it uses ~300ms here. Apparently because we start up and shut down worker threads eight times.

Investigate and fix this.
Comments
Part of the problem is also the CRM FUSE setup: every half an hour some background job seems to take all CPU time for a few seconds, causing very long GC pause times during that time. This explains the issues shown above not clearly related to thread starting at least.
06-05-2014
Some preliminary tests indicate that the problem with the thread synchronization seems to be largely caused by the additional threads provided by hyperthreading. If you set the number of GC threads to the number of real available cores, the synchronization problem seems to largely disappear. Needs some more testing.
16-04-2014
another spike: 6814.511: [GC pause (G1 Evacuation Pause) (young)6815.545: [SoftReference, 0 refs, 0.0000590 secs]6815.545: [WeakReference, 2578 refs, 0.0006040 secs]6815.546: [FinalReference, 313 refs, 0.0011570 secs]6815.547: [PhantomReference, 0 refs, 0.0000080 secs]6815.547: [JNI Weak Reference, 0.0000090 secs], 1.0372680 secs] [Parallel Time: 483.8 ms, GC Workers: 18] [GC Worker Start (ms): 6814511.8 6814511.8 6814511.8 6814511.9 6814604.8 6814604.9 6814604.9 6814605.3 6814605.6 6814605.7 6814605.9 6814605.9 6814606.0 6814606.1 6814606.2 6814606.4 6814606.6 6814606.8 Min: 6814511.8, Avg: 6814584.9, Max: 6814606.8, Diff: 95.0] [Ext Root Scanning (ms): 13.6 13.6 36.2 13.7 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 4.3, Max: 36.2, Diff: 36.2, Sum: 77.2] [Update RS (ms): 245.8 25.0 7.4 77.3 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 19.7, Max: 245.8, Diff: 245.8, Sum: 355.4] [Processed Buffers: 24 46 25 26 0 0 0 0 0 0 0 0 0 0 0 0 0 0 Min: 0, Avg: 6.7, Max: 46, Diff: 46, Sum: 121] [Scan RS (ms): 0.0 0.0 0.3 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.3, Diff: 0.3, Sum: 0.4] [Code Root Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): 3.0 54.3 49.0 2.9 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 6.1, Max: 54.3, Diff: 54.3, Sum: 109.3] [Termination (ms): 0.0 186.3 223.8 222.8 240.3 169.3 173.0 168.9 171.5 168.5 168.4 172.0 171.9 179.8 325.7 325.5 385.8 324.2 Min: 0.0, Avg: 209.9, Max: 385.8, Diff: 385.8, Sum: 3777.7] [Termination Attempts: 1 19 20 1 1 4 1 5 1 1 1 1 1 1 1 1 1 1 Min: 1, Avg: 3.4, Max: 20, Diff: 19, Sum: 62] [GC Worker Other (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): 262.4 279.3 316.7 316.6 240.4 169.3 173.1 168.9 171.5 168.5 168.4 172.0 171.9 179.8 325.8 325.5 385.9 324.2 Min: 168.4, Avg: 240.0, Max: 385.9, Diff: 217.5, Sum: 4320.3] [GC Worker End (ms): 6814774.2 6814791.1 6814828.5 6814828.5 6814845.2 6814774.2 6814778.0 6814774.2 6814777.1 6814774.2 6814774.2 6814777.9 6814777.9 6814785.9 6814932.0 6814932.0 6814992.5 6814931.0 Min: 6814774.2, Avg: 6814824.9, Max: 6814992.5, Diff: 218.3] [Code Root Fixup: 1.0 ms] [Code Root Migration: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.5 ms] [Other: 552.0 ms] [Choose CSet: 0.0 ms] [Ref Proc: 550.9 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.5 ms] [Free CSet: 0.2 ms] [Young Free CSet: 0.2 ms] [Non-Young Free CSet: 0.0 ms] [Eden: 252.0M(252.0M)->0.0B(64.0M) Survivors: 24.0M->36.0M Heap: 1807.3M(2048.0M)->1575.9M(2048.0M)] [Times: user=0.55 sys=0.01, real=1.04 secs] Ref Proc takes 550.9ms. But processed references is not high. Is it related to pending cards?
16-04-2014
more from CRM Fuse log, with log level=finest: 3215.346: [GC pause (G1 Evacuation Pause) (young)3216.109: [SoftReference, 0 refs, 0.0000600 secs]3216.109: [WeakReference, 5691 refs, 0.0014720 secs]3216.111: [FinalReference, 264 refs, 0.0007770 secs]3216.112: [PhantomReference, 0 refs, 0.0000080 secs]3216.112: [JNI Weak Reference, 0.0000090 secs], 0.7674930 secs] [Parallel Time: 760.5 ms, GC Workers: 18] [GC Worker Start (ms): 3215345.9 3215409.2 3215505.2 3215505.2 3215536.2 3215536.2 3215570.7 3215571.4 3215571.4 3215571.6 3215571.6 3215571.8 3215571.8 3215571.9 3215573.2 3215578.6 3215578.6 3215578.8 Min: 3215345.9, Avg: 3215540.0, Max: 3215578.8, Diff: 232.9] [Ext Root Scanning (ms): 40.3 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 2.3, Max: 40.3, Diff: 40.3, Sum: 40.6] [Update RS (ms): 146.7 162.5 36.2 36.1 5.3 5.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 21.8, Max: 162.5, Diff: 162.5, Sum: 391.9] [Processed Buffers: 65 102 8 53 14 15 0 0 0 0 0 0 0 0 0 0 0 0 Min: 0, Avg: 14.3, Max: 102, Diff: 102, Sum: 257] [Scan RS (ms): 0.0 0.0 0.1 0.2 0.0 0.2 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.5] [Code Root Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): 37.7 0.0 29.2 29.1 29.1 29.1 0.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 8.6, Max: 37.7, Diff: 37.7, Sum: 154.5] [Termination (ms): 8.2 6.9 8.1 77.7 8.2 8.2 7.9 7.3 7.3 7.2 76.6 7.0 100.4 100.3 117.4 112.0 527.5 0.0 Min: 0.0, Avg: 66.0, Max: 527.5, Diff: 527.5, Sum: 1188.2] [Termination Attempts: 69 1 107 73 75 80 28 1 1 7 8 1 1 1 1 1 1 1 Min: 1, Avg: 25.4, Max: 107, Diff: 106, Sum: 457] [GC Worker Other (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): 232.9 169.5 73.6 143.0 42.6 42.6 8.1 7.4 7.3 7.2 76.7 7.0 100.5 100.3 117.4 112.1 527.5 0.0 Min: 0.0, Avg: 98.7, Max: 527.5, Diff: 527.5, Sum: 1775.9] [GC Worker End (ms): 3215578.8 3215578.8 3215578.8 3215648.3 3215578.8 3215578.8 3215578.8 3215578.8 3215578.8 3215578.8 3215648.3 3215578.8 3215672.3 3215672.3 3215690.6 3215690.6 3216106.1 3215578.8 Min: 3215578.8, Avg: 3215638.6, Max: 3216106.1, Diff: 527.4] [Code Root Fixup: 1.3 ms] [Code Root Migration: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.5 ms] [Other: 5.2 ms] [Choose CSet: 0.0 ms] [Ref Proc: 4.1 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.6 ms] [Free CSet: 0.2 ms] [Young Free CSet: 0.2 ms] [Non-Young Free CSet: 0.0 ms] [Eden: 240.0M(240.0M)->0.0B(64.0M) Survivors: 40.0M->36.0M Heap: 1790.5M(2048.0M)->1573.4M(2048.0M)] [Times: user=0.43 sys=0.00, real=0.77 secs] thread 2 starts at 3215409.2, but did 0.0 object copy. thread 17 starts at 3215578.6, did nothing but takes 527.5 to terminate. If thread 17 never got scheduled on the cpu, does it need to get cpu to finish termination? thread 18 starts at 3215578.8, did nothing, but takes 0 to terminate.
16-04-2014
At least one of the CRM case is not thread starting issue.(CRM-6-hour run). 17192.289: [GC pause (G1 Evacuation Pause) (young)17192.648: [SoftReference, 0 refs, 0.0000550 secs]17192.648: [WeakReference, 1959 refs, 0.0004660 secs]17192.648: [FinalReference, 125 refs, 0.0003800 secs]17192.648: [PhantomReference, 0 refs, 0.0000070 secs]17192.648: [JNI Weak Reference, 0.0000080 secs], 0.3602630 secs] [Parallel Time: 354.4 ms, GC Workers: 18] [GC Worker Start (ms): Min: 17192289.5, Avg: 17192348.7, Max: 17192365.5, Diff: 76.0] [Ext Root Scanning (ms): Min: 0.0, Avg: 3.9, Max: 68.4, Diff: 68.4, Sum: 70.5] [Update RS (ms): Min: 0.0, Avg: 5.7, Max: 25.4, Diff: 25.4, Sum: 103.0] [Processed Buffers: Min: 0, Avg: 8.3, Max: 35, Diff: 35, Sum: 149] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3] [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): Min: 0.0, Avg: 6.6, Max: 13.2, Diff: 13.2, Sum: 119.0] [Termination (ms): Min: 0.0, Avg: 17.7, Max: 279.1, Diff: 279.1, Sum: 318.4] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): Min: 0.0, Avg: 34.0, Max: 296.0, Diff: 296.0, Sum: 611.5] [GC Worker End (ms): Min: 17192365.5, Avg: 17192382.6, Max: 17192643.8, Diff: 278.3] [Code Root Fixup: 1.7 ms] [Code Root Migration: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.3 ms] [Other: 3.8 ms] [Choose CSet: 0.0 ms] [Ref Proc: 2.9 ms] [Ref Enq: 0.1 ms] [Redirty Cards: 0.5 ms] [Free CSet: 0.1 ms] [Eden: 160.0M(160.0M)->0.0B(160.0M) Survivors: 28.0M->24.0M Heap: 1799.0M(2048.0M)->1647.4M(2048.0M)] [Times: user=0.25 sys=0.01, real=0.36 secs] The difference in starting time is 76ms, the difference in ending time is 278.3ms.It could be 1 thread starts late and slow finishing the job, or some other threads are slow. Can not tell from this log as the per thread information is not included.
15-04-2014
One problem could be the use of the Hotspot internal synchronization primitives for the work gang code. Another potential cause could be log writing taking very long because of background writes to disk. See http://mail.openjdk.java.net/pipermail/hotspot-gc-use/2014-April/001835.html for this issue. The random long pauses on CRM Fuse also occur with parallel gc.
15-04-2014