United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: 7068240 G1: Long "parallel other time" and "ext root scanning" when running specific benchmark
7068240 : G1: Long "parallel other time" and "ext root scanning" when running specific benchmark

Details
Type:
Bug
Submit Date:
2011-07-18
Status:
Closed
Updated Date:
2011-11-25
Project Name:
JDK
Resolved Date:
2011-09-30
Component:
hotspot
OS:
generic
Sub-Component:
gc
CPU:
generic
Priority:
P4
Resolution:
Fixed
Affected Versions:
7u2
Fixed Versions:
hs22

Related Reports
Backport:
Backport:

Sub Tasks

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
                                     
2011-09-12
EVALUATION

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

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

http://hg.openjdk.java.net/hsx/hotspot-gc/hotspot/rev/14a2fd14c0db
                                     
2011-08-02
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.
                                     
2011-08-02



Hardware and Software, Engineered to Work Together