What is the logic that G1GC follows when triggering young/mixed/full GC
Haim Yadid
haim at performize-it.com
Mon Aug 20 03:29:24 PDT 2012
I am evaluating G1GC as a candidate to solve GC pause of an application
with 20GB heap.
It seems like from time to time G1 is issuing a Full GC which leads to a
long pause ( at least 10 seconds).
In addition from time to time it is triggering the mixed mode and then it
breaches the soft real time requirement I set ( 100 ms max pause time)
Why does it happen ? What are the reasons for G1 to initiate a full GC. Why
does the mixed mode collections are so long ?
Attaching part of the log
2012-08-19T23:53:26.414+0000: 36846.868: [GC pause (young), 0.99116700 secs]
[Parallel Time: 957.3 ms]
[GC Worker Start (ms): 36846868.9 36846868.9 36846868.9
36846868.9 36846868.9 36846868.9 36846868.9 36846868.9 36846868.9
36846868.9 36846868.9 36846869.0 36846869.0
Avg: 36846868.9, Min: 36846868.9, Max: 36846869.0, Diff: 0.1]
[Ext Root Scanning (ms): 1.7 1.5 1.9 2.2 1.8 1.7 1.7 1.6 1.5
1.7 1.7 1.4 1.9
Avg: 1.7, Min: 1.4, Max: 2.2, Diff: 0.8]
[Update RS (ms): 9.8 9.8 9.9 9.3 9.6 10.0 10.4 10.0 10.7
11.4 11.0 10.1 9.6
Avg: 10.1, Min: 9.3, Max: 11.4, Diff: 2.1]
[Processed Buffers : 11 13 13 15 18 10 20 11 12 13 11 12 9
Sum: 168, Avg: 12, Min: 9, Max: 20, Diff: 11]
[Scan RS (ms): 67.9 67.8 67.5 67.8 67.7 67.6 67.2 67.6 67.0
66.0 66.5 67.9 67.7
Avg: 67.4, Min: 66.0, Max: 67.9, Diff: 1.9]
[Object Copy (ms): 875.3 875.3 876.5 875.4 875.6 875.3 875.5
875.3 875.4 875.6 875.7 875.2 875.4
Avg: 875.5, Min: 875.2, Max: 876.5, Diff: 1.2]
[Termination (ms): 1.1 1.1 0.0 1.0 1.0 1.2 0.9 1.2 1.1 1.0
0.9 1.1 1.2
Avg: 1.0, Min: 0.0, Max: 1.2, Diff: 1.2]
[Termination Attempts : 1974 1909 1 1892 1665 2133 1751 2073 2045
1701 1756 2077 2158
Sum: 23135, Avg: 1779, Min: 1, Max: 2158, Diff: 2157]
[GC Worker End (ms): 36847824.7 36847824.8 36847824.8 36847824.8
36847824.7 36847824.8 36847824.8 36847824.7 36847824.8 36847824.8
36847824.8 36847824.7 36847824.8
Avg: 36847824.8, Min: 36847824.7, Max: 36847824.8, Diff: 0.1]
[GC Worker (ms): 955.9 955.9 955.9 955.9 955.8 955.9 955.9
955.8 955.8 955.9 955.9 955.8 955.8
Avg: 955.9, Min: 955.8, Max: 955.9, Diff: 0.2]
[GC Worker Other (ms): 1.5 1.8 1.5 1.5 1.6 1.6 1.6 1.6 1.6
1.6 1.6 1.6 1.6
Avg: 1.6, Min: 1.5, Max: 1.8, Diff: 0.3]
[Clear CT: 1.7 ms]
[Other: 32.1 ms]
[Choose CSet: 0.3 ms]
[Ref Proc: 0.7 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 12.4 ms]
[Eden: 3776M(3776M)->0B(3306M) Survivors: 4096K->474M Heap:
8949M(18908M)->6839M(18908M)]
[Times: user=12.45 sys=0.03, real=0.99 secs]
2012-08-19T23:59:23.636+0000: 37204.090: [GC pause (mixed), 1.48753900 secs]
[Parallel Time: 1439.9 ms]
[GC Worker Start (ms): 37204093.5 37204093.5 37204093.5
37204093.5 37204093.5 37204093.6 37204093.6 37204093.6 37204093.6
37204093.6 37204093.6 37204093.6 37204093.6
Avg: 37204093.6, Min: 37204093.5, Max: 37204093.6, Diff: 0.1]
[Ext Root Scanning (ms): 1.5 2.0 1.9 1.4 1.6 1.6 1.4 1.5 1.5
1.6 1.4 1.6 1.4
Avg: 1.6, Min: 1.4, Max: 2.0, Diff: 0.6]
[Update RS (ms): 14.7 12.0 11.5 12.4 11.5 11.6 11.9 11.5
15.5 11.8 11.9 12.8 11.8
Avg: 12.4, Min: 11.5, Max: 15.5, Diff: 4.0]
[Processed Buffers : 10 7 7 8 21 7 7 32 8 7 8 7 8
Sum: 137, Avg: 10, Min: 7, Max: 32, Diff: 25]
[Scan RS (ms): 144.8 146.8 147.2 147.0 147.9 147.6 147.3
147.9 143.9 147.6 147.5 146.1 147.6
Avg: 146.9, Min: 143.9, Max: 147.9, Diff: 4.0]
[Object Copy (ms): 1271.4 1271.8 1273.0 1271.7 1271.7 1271.6
1271.8 1271.6 1272.4 1277.3 1271.6 1273.1 1273.0
Avg: 1272.5, Min: 1271.4, Max: 1277.3, Diff: 5.8]
[Termination (ms): 6.0 5.8 4.7 5.9 5.5 5.9 5.8 5.6 4.9 0.0
5.9 4.4 4.4
Avg: 5.0, Min: 0.0, Max: 6.0, Diff: 6.0]
[Termination Attempts : 8002 7759 6378 7864 7158 7929 7776 7293
6256 1 7901 5835 5842
Sum: 85994, Avg: 6614, Min: 1, Max: 8002, Diff: 8001]
[GC Worker End (ms): 37205531.9 37205531.9 37205531.9 37205531.9
37205532.0 37205531.9 37205531.9 37205531.9 37205532.0 37205532.0
37205531.9 37205532.0 37205532.0
Avg: 37205531.9, Min: 37205531.9, Max: 37205532.0, Diff: 0.1]
[GC Worker (ms): 1438.4 1438.4 1438.3 1438.4 1438.4 1438.3
1438.3 1438.4 1438.4 1438.4 1438.3 1438.4 1438.4
Avg: 1438.4, Min: 1438.3, Max: 1438.4, Diff: 0.1]
[GC Worker Other (ms): 1.6 1.6 1.6 1.6 1.6 1.6 1.7 1.6 1.7
1.7 1.7 1.9 1.7
Avg: 1.6, Min: 1.6, Max: 1.9, Diff: 0.3]
[Clear CT: 2.1 ms]
[Other: 45.6 ms]
[Choose CSet: 2.3 ms]
[Ref Proc: 0.6 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 15.8 ms]
[Eden: 3306M(3306M)->0B(3532M) Survivors: 474M->474M Heap:
13220M(20036M)->10771M(20036M)]
[Times: user=18.47 sys=0.10, real=1.49 secs]
2012-08-19T23:59:31.632+0000: 37212.087: [GC pause (mixed), 0.79556800 secs]
[Parallel Time: 766.4 ms]
[GC Worker Start (ms): 37212091.2 37212091.2 37212091.2
37212091.2 37212091.2 37212091.2 37212091.2 37212091.3 37212091.3
37212091.3 37212091.3 37212091.3 37212091.3
Avg: 37212091.3, Min: 37212091.2, Max: 37212091.3, Diff: 0.1]
[Ext Root Scanning (ms): 1.5 2.1 1.4 1.5 1.4 2.0 1.6 1.5 2.0
1.5 1.6 1.1 1.4
Avg: 1.6, Min: 1.1, Max: 2.1, Diff: 1.0]
[Update RS (ms): 15.3 14.6 15.4 18.6 15.4 14.6 15.1 15.3
14.6 15.4 15.1 15.2 15.5
Avg: 15.4, Min: 14.6, Max: 18.6, Diff: 4.0]
[Processed Buffers : 40 30 31 40 34 30 31 35 30 38 32 38 30
Sum: 439, Avg: 33, Min: 30, Max: 40, Diff: 10]
[Scan RS (ms): 70.4 70.4 70.4 67.0 70.4 70.4 70.3 70.4 70.4
70.3 70.3 70.5 70.1
Avg: 70.1, Min: 67.0, Max: 70.5, Diff: 3.4]
[Object Copy (ms): 671.5 670.5 670.6 670.5 670.5 670.8 670.6
670.5 670.6 671.0 670.9 677.6 670.8
Avg: 671.3, Min: 670.5, Max: 677.6, Diff: 7.1]
[Termination (ms): 6.2 7.3 7.2 7.2 7.1 7.1 7.2 7.1 7.2 6.6
6.9 0.0 7.0
Avg: 6.5, Min: 0.0, Max: 7.3, Diff: 7.3]
[Termination Attempts : 7855 8294 8154 8366 8234 8178 8029 7990
8054 8147 7594 1 8133
Sum: 97029, Avg: 7463, Min: 1, Max: 8366, Diff: 8365]
[GC Worker End (ms): 37212856.1 37212856.1 37212856.1 37212856.2
37212856.2 37212856.1 37212856.2 37212856.1 37212856.2 37212856.2
37212856.1 37212856.2 37212856.2
Avg: 37212856.2, Min: 37212856.1, Max: 37212856.2, Diff: 0.1]
[GC Worker (ms): 764.9 764.9 764.9 764.9 765.0 764.9 764.9
764.9 764.9 764.9 764.8 764.9 764.9
Avg: 764.9, Min: 764.8, Max: 765.0, Diff: 0.1]
[GC Worker Other (ms): 1.5 1.5 1.6 1.6 1.6 1.6 1.6 1.6 1.6
1.6 1.6 2.1 1.6
Avg: 1.6, Min: 1.5, Max: 2.1, Diff: 0.5]
[Clear CT: 2.5 ms]
[Other: 26.6 ms]
[Choose CSet: 2.7 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 10.1 ms]
[Eden: 1318M(3532M)->0B(3822M) Survivors: 474M->266M Heap:
13077M(20444M)->11364M(20444M)]
[Times: user=10.01 sys=0.00, real=0.79 secs]
2012-08-19T23:59:47.406+0000: 37227.860: [GC pause (mixed), 2.20691100 secs]
[Parallel Time: 2151.1 ms]
[GC Worker Start (ms): 37227867.4 37227867.4 37227867.4
37227867.4 37227867.4 37227867.4 37227867.4 37227867.4 37227867.5
37227867.5 37227867.5 37227867.5 37227867.5
Avg: 37227867.4, Min: 37227867.4, Max: 37227867.5, Diff: 0.1]
[Ext Root Scanning (ms): 1.5 1.9 1.5 1.6 2.2 1.6 1.2 1.6 2.1
1.3 1.4 1.3 1.4
Avg: 1.6, Min: 1.2, Max: 2.2, Diff: 0.9]
[Update RS (ms): 19.2 17.1 19.3 19.6 17.4 20.7 17.7 18.0
19.8 17.9 17.7 17.7 21.3
Avg: 18.7, Min: 17.1, Max: 21.3, Diff: 4.1]
[Processed Buffers : 9 7 8 5 9 6 11 9 7 8 8 8 7
Sum: 102, Avg: 7, Min: 5, Max: 11, Diff: 6]
[Scan RS (ms): 1384.6 1394.3 1384.9 1395.4 1396.9 1380.9
1386.4 1395.6 1395.8 1384.9 1399.2 1401.8 1387.4
Avg: 1391.4, Min: 1380.9, Max: 1401.8, Diff: 20.8]
[Object Copy (ms): 740.2 731.6 739.9 728.2 728.2 741.4 744.2
729.6 727.0 740.8 726.4 723.9 734.7
Avg: 733.5, Min: 723.9, Max: 744.2, Diff: 20.3]
[Termination (ms): 4.0 4.6 3.9 4.8 4.8 4.9 0.0 4.8 4.7 4.6
4.9 4.8 4.8
Avg: 4.3, Min: 0.0, Max: 4.9, Diff: 4.9]
[Termination Attempts : 5659 7036 5875 6888 6896 6924 1 7335 6824
7011 7219 7016 7148
Sum: 81832, Avg: 6294, Min: 1, Max: 7335, Diff: 7334]
[GC Worker End (ms): 37230017.1 37230017.0 37230017.0 37230017.1
37230017.1 37230017.1 37230017.1 37230017.1 37230017.0 37230017.0
37230017.0 37230017.0 37230017.1
Avg: 37230017.1, Min: 37230017.0, Max: 37230017.1, Diff: 0.1]
[GC Worker (ms): 2149.7 2149.6 2149.6 2149.7 2149.6 2149.6
2149.7 2149.6 2149.6 2149.5 2149.6 2149.6 2149.6
Avg: 2149.6, Min: 2149.5, Max: 2149.7, Diff: 0.2]
[GC Worker Other (ms): 1.7 1.6 1.6 1.6 1.6 1.6 1.6 1.6 1.6
1.6 1.6 1.6 1.7
Avg: 1.6, Min: 1.6, Max: 1.7, Diff: 0.1]
[Clear CT: 3.2 ms]
[Other: 52.6 ms]
[Choose CSet: 6.4 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 16.7 ms]
[Eden: 3152M(3822M)->0B(3912M) Survivors: 266M->176M Heap:
14601M(20444M)->11309M(20444M)]
[Times: user=28.03 sys=0.01, real=2.21 secs]
2012-08-19T23:59:49.615+0000: 37230.069: [Full GC 11309M->2021M(7604M),
10.4855330 secs]
[Times: user=16.90 sys=0.55, real=10.48 secs]
2012-08-20T00:00:07.434+0000: 37247.889: [GC pause (young), 0.24075000 secs]
[Parallel Time: 230.3 ms]
[GC Worker Start (ms): 37247889.7 37247889.7 37247889.7
37247889.7 37247889.7 37247889.8 37247889.8 37247889.8 37247889.8
37247889.8 37247889.8 37247889.8 37247889.8
Avg: 37247889.8, Min: 37247889.7, Max: 37247889.8, Diff: 0.1]
[Ext Root Scanning (ms): 2.3 2.4 2.2 2.3 2.6 2.4 2.9 2.3 2.1
2.4 2.1 2.2 2.3
Avg: 2.3, Min: 2.1, Max: 2.9, Diff: 0.8]
[Update RS (ms): 10.0 10.5 9.6 9.4 9.2 8.8 8.1 9.2 11.8
11.2 9.7 9.3 9.1
Avg: 9.7, Min: 8.1, Max: 11.8, Diff: 3.7]
[Processed Buffers : 8 8 9 7 9 16 12 14 7 8 7 8 8
Sum: 121, Avg: 9, Min: 7, Max: 16, Diff: 9]
[Scan RS (ms): 12.1 11.6 12.6 12.6 12.6 13.1 13.1 13.0 10.5
10.8 12.6 12.8 13.1
Avg: 12.4, Min: 10.5, Max: 13.1, Diff: 2.6]
[Object Copy (ms): 204.4 204.3 204.3 204.4 204.4 204.4 204.6
204.3 204.3 204.3 204.3 204.3 204.2
Avg: 204.3, Min: 204.2, Max: 204.6, Diff: 0.4]
[Termination (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
Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0]
[Termination Attempts : 3 2 3 2 3 3 2 3 1 3 1 3 2
Sum: 31, Avg: 2, Min: 1, Max: 3, Diff: 2]
[GC Worker End (ms): 37248118.6 37248118.6 37248118.6 37248118.6
37248118.6 37248118.5 37248118.5 37248118.6 37248118.6 37248118.6
37248118.6 37248118.6 37248118.6
Avg: 37248118.6, Min: 37248118.5, Max: 37248118.6, Diff: 0.1]
[GC Worker (ms): 228.9 228.9 228.8 228.8 228.9 228.8 228.8
228.9 228.8 228.8 228.8 228.8 228.8
Avg: 228.8, Min: 228.8, Max: 228.9, Diff: 0.1]
[GC Worker Other (ms): 1.5 1.5 1.6 1.5 1.6 1.6 1.6 1.6 1.6
1.6 1.6 1.6 1.6
Avg: 1.6, Min: 1.5, Max: 1.6, Diff: 0.1]
[Clear CT: 0.9 ms]
[Other: 9.5 ms]
[Choose CSet: 0.1 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 4.2 ms]
[Eden: 1520M(3912M)->0B(1330M) Survivors: 0B->190M Heap:
3945M(7604M)->2847M(7604M)]
[Times: user=2.99 sys=0.00, real=0.24 secs]
2012-08-20T00:00:16.250+0000: 37256.705: [GC pause (young), 0.19628600 secs]
[Parallel Time: 187.5 ms]
[GC Worker Start (ms): 37256705.1 37256705.1 37256705.1
37256705.2 37256705.2 37256705.2 37256705.2 37256705.2 37256705.2
37256705.2 37256705.2 37256705.2 37256705.2
Avg: 37256705.2, Min: 37256705.1, Max: 37256705.2, Diff: 0.1]
[Ext Root Scanning (ms): 1.4 1.4 1.5 1.6 1.6 1.5 1.6 1.4 2.1
1.2 1.9 1.4 1.3
Avg: 1.5, Min: 1.2, Max: 2.1, Diff: 0.9]
[Update RS (ms): 4.9 5.2 5.2 4.9 4.9 5.1 4.9 4.9 4.4 5.3
4.6 5.2 5.1
Avg: 5.0, Min: 4.4, Max: 5.3, Diff: 0.9]
[Processed Buffers : 8 9 9 9 12 11 8 8 11 10 8 13 9
Sum: 125, Avg: 9, Min: 8, Max: 13, Diff: 5]
[Scan RS (ms): 14.5 14.5 14.4 14.5 14.6 14.3 14.5 14.6 14.7
14.5 14.3 14.3 14.6
Avg: 14.5, Min: 14.3, Max: 14.7, Diff: 0.4]
[Object Copy (ms): 165.0 164.9 164.8 164.8 164.8 164.9 164.8
164.8 164.5 164.7 164.9 164.8 164.6
Avg: 164.8, Min: 164.5, Max: 165.0, Diff: 0.5]
[Termination (ms): 0.1 0.0 0.2 0.1 0.1 0.1 0.1 0.2 0.2 0.2
0.2 0.1 0.2
Avg: 0.1, Min: 0.0, Max: 0.2, Diff: 0.2]
[Termination Attempts : 299 1 263 259 188 185 247 256 307 311 318
270 304
Sum: 3208, Avg: 246, Min: 1, Max: 318, Diff: 317]
[GC Worker End (ms): 37256891.2 37256891.2 37256891.2 37256891.2
37256891.2 37256891.1 37256891.2 37256891.2 37256891.2 37256891.2
37256891.2 37256891.2 37256891.2
Avg: 37256891.2, Min: 37256891.1, Max: 37256891.2, Diff: 0.1]
[GC Worker (ms): 186.1 186.0 186.1 186.1 186.1 186.0 186.0
186.0 186.0 186.0 186.0 186.0 185.9
Avg: 186.0, Min: 185.9, Max: 186.1, Diff: 0.1]
[GC Worker Other (ms): 1.5 1.6 1.5 1.5 1.5 1.6 1.6 1.6 1.6
1.6 1.6 1.6 1.6
Avg: 1.6, Min: 1.5, Max: 1.6, Diff: 0.1]
[Clear CT: 0.8 ms]
[Other: 8.0 ms]
[Choose CSet: 0.1 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 4.0 ms]
[Eden: 1330M(1330M)->0B(1332M) Survivors: 190M->188M Heap:
4487M(7604M)->3343M(7604M)]
[Times: user=2.43 sys=0.00, real=0.20 secs]
2012-08-20T00:00:27.180+0000: 37267.635: [GC pause (young), 0.14220300 secs]
[Parallel Time: 134.8 ms]
[GC Worker Start (ms): 37267634.8 37267634.8 37267634.8
37267634.8 37267634.8 37267634.8 37267634.8 37267634.8 37267634.8
37267634.8 37267634.8 37267634.8 37267634.8
Avg: 37267634.8, Min: 37267634.8, Max: 37267634.8, Diff: 0.1]
[Ext Root Scanning (ms): 2.2 1.7 1.6 1.6 1.4 1.5 1.3 1.4 1.6
1.6 1.9 1.6 1.3
Avg: 1.6, Min: 1.3, Max: 2.2, Diff: 0.9]
[Update RS (ms): 14.8 15.0 14.9 15.2 15.5 15.1 15.5 15.5
15.2 15.0 15.0 16.1 15.2
Avg: 15.2, Min: 14.8, Max: 16.1, Diff: 1.3]
[Processed Buffers : 8 12 13 13 11 5 11 9 8 8 10 19 11
Sum: 138, Avg: 10, Min: 5, Max: 19, Diff: 14]
[Scan RS (ms): 0.7 0.7 0.9 0.8 0.7 0.9 0.6 0.5 0.7 0.9 0.5
0.0 0.9
Avg: 0.7, Min: 0.0, Max: 0.9, Diff: 0.9]
[Object Copy (ms): 115.5 115.6 115.6 115.3 115.3 115.4 115.5
115.4 115.5 115.3 115.4 115.2 115.4
Avg: 115.4, Min: 115.2, Max: 115.6, Diff: 0.4]
[Termination (ms): 0.0 0.3 0.2 0.3 0.3 0.3 0.3 0.3 0.3 0.3
0.3 0.3 0.3
Avg: 0.3, Min: 0.0, Max: 0.3, Diff: 0.3]
[Termination Attempts : 1 471 475 570 615 560 605 595 464 532 616
469 593
Sum: 6566, Avg: 505, Min: 1, Max: 616, Diff: 615]
[GC Worker End (ms): 37267768.0 37267768.0 37267768.1 37267768.1
37267768.1 37267768.1 37267768.1 37267768.0 37267768.1 37267768.1
37267768.1 37267768.1 37267768.1
Avg: 37267768.1, Min: 37267768.0, Max: 37267768.1, Diff: 0.1]
[GC Worker (ms): 133.3 133.3 133.4 133.3 133.3 133.3 133.3
133.2 133.3 133.3 133.2 133.2 133.3
Avg: 133.3, Min: 133.2, Max: 133.4, Diff: 0.1]
[GC Worker Other (ms): 1.5 1.5 1.5 1.5 1.5 1.6 1.6 1.6 1.6
1.6 1.6 1.6 1.6
Avg: 1.6, Min: 1.5, Max: 1.6, Diff: 0.1]
[Clear CT: 0.4 ms]
[Other: 7.0 ms]
[Choose CSet: 0.1 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 3.6 ms]
[Eden: 1332M(1332M)->0B(1482M) Survivors: 188M->38M Heap:
4675M(7604M)->3370M(7604M)]
[Times: user=1.76 sys=0.00, real=0.14 secs]
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20120820/a86c4623/attachment-0001.html
More information about the hotspot-gc-use
mailing list