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]
|