JDK-7068240 : G1: Long "parallel other time" and "ext root scanning" when running specific benchmark
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 7u2
  • Priority: P4
  • Status: Closed
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2011-07-18
  • Updated: 2011-11-25
  • Resolved: 2011-09-30
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.
JDK 7 JDK 8 Other
7u2Fixed 8Fixed hs22Fixed
Description
While running performance runs of the ATG CRM demo, it was observed in the GC logs the parallel other time for several evacuation pauses (both fully young and partially young) was almnost a fairly constant 50ms (independent of the time for the pause as a whole - both 150ms and 850ms pauses show a similar value for parallel other time).

Here is an example:

5324.587: [GC pause (young), 0.14082100 secs]
   [SATB Drain Time:   0.2 ms]
   [Parallel Time: 133.0 ms]
      [GC Worker Start Time (ms):  5324587.4  5324587.4  5324587.4  5324587.4  5324587.4  5324588.1  5324588.1  5324588.1  5324588.1  5324588.1  5324589.1  5324589.1  5324589.2  5324589.2  5324589.2  5324590.2  5324591.3  5324591.3  5324591.3  5324591.3  5324591.3  5324592.2  5324594.3  5324600.3  5324600.6  5324600.7  5324600.7  5324601.7  5324606.1  5324606.1  5324606.1  5324606.1  5324606.1  5324606.1  5324606.1  5324606.1  5324607.0  5324607.1  5324607.6  5324607.6  5324607.9  5324608.0  5324608.2  5324608.3  5324608.3  5324608.3  5324608.3  5324608.3  5324608.7  5324608.7  5324608.7  5324609.0  5324609.0
       Avg: 5324599.0, Min: 5324587.4, Max: 5324609.0, Diff:  21.7]
      [Update RS (ms):  4.6  8.5  4.7  5.2  6.2  0.0  6.9  3.8  4.3  4.5  6.1  5.4  4.7  1.9  5.5  0.0  5.2  6.7  5.5  4.6  5.3  5.3  6.9  3.4  4.8  3.0  6.0  3.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  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   2.5, Min:   0.0, Max:   8.5, Diff:   8.5]
         [Processed Buffers : 9 5 3 3 1 0 1 6 6 3 6 4 6 2 1 0 4 1 2 8 2 1 1 4 1 3 3 4 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
          Sum: 90, Avg: 1, Min: 0, Max: 9, Diff: 9]
      [Ext Root Scanning (ms):  12.2  11.0  12.7  11.0  11.1  22.5  10.4  11.7  10.1  12.2  9.9  11.5  9.9  12.9  10.7  86.6  8.3  7.9  8.1  7.8  8.7  6.7  4.6  1.2  0.9  0.9  0.9  0.2  0.9  0.9  0.9  0.9  0.9  0.9  0.9  0.9  0.2  0.2  0.2  0.2  0.2  0.2  0.2  0.2  0.2  0.2  0.2  0.2  0.2  0.2  0.2  0.2  0.2
       Avg:   6.3, Min:   0.2, Max:  86.6, Diff:  86.4]
      [Mark Stack 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  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  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
       Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
      [Scan RS (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  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  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
       Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
      [Object Copy (ms):  4.1  0.9  4.2  3.4  3.4  3.6  1.6  4.5  5.3  2.3  1.8  1.1  5.1  3.7  2.3  0.1  3.9  1.1  3.1  4.2  3.8  3.8  1.2  2.1  0.8  3.3  0.0  2.4  0.2  0.2  0.2  0.2  0.2  0.2  0.2  0.0  0.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  0.0  0.0  0.0  0.0
       Avg:   1.5, Min:   0.0, Max:   5.3, Diff:   5.2]
      [Termination (ms):  70.8  71.2  67.9  72.0  71.0  62.7  72.1  71.1  69.3  72.1  72.0  71.9  70.1  71.3  71.5  0.0  70.5  69.8  71.2  69.1  69.8  68.7  69.8  69.9  72.1  69.0  69.3  71.1  69.7  71.8  69.7  69.7  69.7  69.7  71.9  69.9  71.6  71.7  71.1  71.3  71.1  68.7  70.8  70.7  70.4  68.4  70.5  70.5  68.0  70.2  68.0  69.9  67.8
       Avg:  68.9, Min:   0.0, Max:  72.1, Diff:  72.1]
         [Termination Attempts : 1 2 2 7 2 1 5 2 2 10 4 9 1 4 2 1 1 10 1 1 1 1 11 6 13 2 4 1 7 9 8 11 9 14 13 1 4 7 3 1 1 1 1 1 1 1 1 1 1 1 1 1 1
          Sum: 207, Avg: 3, Min: 1, Max: 14, Diff: 13]
      [GC Worker End Time (ms):  5324679.0  5324679.1  5324679.1  5324679.0  5324679.1  5324679.2  5324679.1  5324679.2  5324679.2  5324679.2  5324679.0  5324679.0  5324679.0  5324679.0  5324679.1  5324678.9  5324679.2  5324679.1  5324679.2  5324679.0  5324679.0  5324679.4  5324679.2  5324679.2  5324679.2  5324679.1  5324679.1  5324679.2  5324678.9  5324679.0  5324678.9  5324679.2  5324679.5  5324679.3  5324679.1  5324679.1  5324679.0  5324679.1  5324679.0  5324679.2  5324679.2  5324679.2  5324679.2  5324679.2  5324679.0  5324678.9  5324679.1  5324679.1  5324679.0  5324679.1  5324679.0  5324679.1  5324679.2
       Avg: 5324679.1, Min: 5324678.9, Max: 5324679.5, Diff:   0.6]
      [GC Worker Times (ms):  91.6  91.8  91.7  91.7  91.7  91.1  90.9  91.1  91.1  91.1  89.9  89.9  89.8  89.8  89.9  88.8  88.0  87.8  87.9  87.7  87.7  87.2  84.9  79.0  78.6  78.4  78.4  77.5  72.8  72.9  72.8  73.1  73.4  73.1  73.0  73.0  71.9  72.0  71.3  71.5  71.3  71.3  71.0  71.0  70.7  70.6  70.8  70.7  70.3  70.4  70.3  70.1  70.2
       Avg:  80.1, Min:  70.1, Max:  91.8, Diff:  21.6]
      [Other:  53.9 ms]
   [Clear CT:   0.5 ms]
   [Other:   7.1 ms]
      [Choose CSet:   0.0 ms]
   [ 50696M->50682M(56320M)]
 [Times: user=1.80 sys=0.02, real=0.14 secs]

Comments
EVALUATION See main CR
12-09-2011

EVALUATION http://hg.openjdk.java.net/hsx/hotspot-rt/hotspot/rev/14a2fd14c0db
17-08-2011

EVALUATION http://hg.openjdk.java.net/hsx/hotspot-main/hotspot/rev/14a2fd14c0db
17-08-2011

SUGGESTED FIX In G1CollectedHeap::g1_process_strong_roots, move the scanning of the reference processor's discovered lists to before RSet updating and scanning. Also capture any objects to be copied in a BufferingOopClosure (like the other external roots) so that the actual copying is attributed to the object copy time.
02-08-2011

EVALUATION http://hg.openjdk.java.net/hsx/hotspot-gc/hotspot/rev/14a2fd14c0db
02-08-2011