Talk about the JVM (iv) in-depth understanding major GC, full GC, CMS

A lot of people can't tell the major GC, the full GC concept, in fact I checked the information, and did not find a very accurate definition of major GC and full GC concept. The confusion between these two concepts may be confusing: Does the full GC cause minor GC?

After a series of lookups and analysis of the performance of the JVM, it is possible to define the full GC and major GC next, which is a concept and justification.

This article major gcs–separating myth from Reality Basic discussion is also the problem, but it does not give practical proof.

We can think of major GC = = Full GC, they are a concept that is for the old age/permanent generation of GC. Because the name full will make people wonder, in the end will not first minor GC. In fact, the full GC itself does not first minor GC, we can configure, let the full GC before the minor GC, because many objects in the old age will refer to the new generation of objects, a first minor GC can increase the speed of the old GC. For example, the old age when using CMS, set Cmsscavengebeforeremark optimization, let the CMS remark before the first minor GC.

Figuring out that the full GC was meant purely for the old age, we went further into understanding the meaning of full GC. Because CMS can be divided mainly into initial mark (Stop the World), concurrent mark, remark (stop of the world), concurrent sweep several stages, of which initial mark and REM Ark will stop the world.

In this talk about the JVM (ii) say some of the common concepts of GC We said that at least the number of times the CMS will give the full GC + 2, because the number of full GC is determined by the number of stops in the old age GC .

Another look at the time definition of the full GC is that it also refers to the age of the old GC when stop the world. Let's look at an example to prove it.

This is a log I grabbed from a tomcat JVM GC log that used the CMS collector in the old age

2014-12-08t17:24:18.514+0800:77443.326: [GC [1 <strong><span style= "color: #FF0000;" &GT;CMS-INITIAL-MARK:1382782K (1843200K)] 1978934K (4710400K), 0.0702700 secs] [times:user=0.07 sys=0.00, real=0.07 Secs]</span></strong> 2014-12-08t17:24:18.586+0800:77443.398: [Cms-concurrent-mark-start] 2014-12-08t17:24:19.890+0800:77444.702: [cms-concurrent-mark:1.206/1.303 secs] [times:user=2.80 sys=0.07, real=1.30 secs] 2014-12-08t17:24:19.890+0800:77444.702: [cms-concurrent-preclean-start]2014-12-08t17:24:19.906+0800: 77444.718: [cms-concurrent-preclean:0.015/0.015 secs] [times:user=0.02 sys=0.00, real=0.02 secs] 2014-12-08T17 : 24:19.906+0800:77444.718: [Cms-concurrent-abortable-preclean-start] Cms:abort Preclean due to time 2014-12-08T17 : 24:25.181+0800:77449.993: [cms-concurrent-abortable-preclean:5.241/5.275 secs] [times:user=6.03 sys=0.09, real= 5.27 secs] 2014-12-08t17:24:25.187+0800:77449.999: [Gc[yg occupancy:749244 K (2867200 k)]77450.000: [Rescan (parallel) , 0.0276780 secs]77450.028: [Weak refs processing, 0.2029030 secs] [<span style= "color: #FF0000;" ><strong>1 cms-remark:1382782k (1843200K)] 2132027K (4710400K), 0.2340660 secs] [times:user=0.43 sys=0.00, real=0.23 Secs</strong></span>] 2014-12-08t17:24:25.424+0800:77450.236: [CMS-concurrent-sweep-start] 2014-12-08t17:24:27.420+0800:77452.232: [cms-concurrent-sweep:1.918/1.996 secs] [times:user=2.61 sys=0.05, real= 2.00 secs] 2014-12-08t17:24:27.421+0800:77452.233: [cms-concurrent-reset-start]2014-12-08t17:24:27.430+0800: 77452.242: [cms-concurrent-reset:0.010/0.010 secs] [times:user=0.01 sys=0.00, real=0.01 secs] 2014-12-09t12:45:05.545 +0800:147090.358: [GC [<span style= "color: #FF0000;] ><strong>1 cms-initial-mark:1384080k (1843200K)] 2013429K (4710400K), 0.0656230 secs] [times:user=0.06 sys= 0.00, real=0.07 Secs</strong></span>] 2014-12-09t12:45:05.613+0800:147090.425: [ Cms-concurrent-mark-start]2014-12-09t12:45:06.848+0800:147091.660: [cms-concurrent-mark:1.196/1.235 secs] [times:user=2.77 sys=0.03, real=1.23 secs] 2014-12-09t12:45:06.849+ 0800:147091.661: [cms-concurrent-preclean-start]2014-12-09t12:45:06.862+0800:147091.674: [ cms-concurrent-preclean:0.013/0.013 secs] [times:user=0.02 sys=0.00, real=0.02 secs] 2014-12-09t12:45:06.862+0800: 147091.674: [Cms-concurrent-abortable-preclean-start] Cms:abort Preclean due to time 2014-12-09t12:45:11.874+0800: 147096.686: [cms-concurrent-abortable-preclean:4.948/5.012 secs] [times:user=6.04 sys=0.10, real=5.01 secs] 2014-12-09t12:45:11.882+0800:147096.694: [Gc[yg occupancy:815312 K (2867200 k)]147096.695: [Rescan (parallel), 0.04767 secs]147096.743: [Weak refs processing, 0.1565260 secs] [1 <span style= "color: #FF0000;" ><strong>cms-remark:1384080k (1843200K)] 2199393K (4710400K), 0.2064660 secs] [times:user=0.48 sys=0.00, Real =0.20 Secs</strong></span>] 2014-12-09t12:45:12.091+0800:147096.903: [CMS-concurrent-sweep-start]2014 -12-09t12:45:14.078+0800:147098.890: [cms-concurrent-sweep:1.934/1.986 secs] [times:user=2.43 sys=0.04, real=1.99 secs] 2014-12-09t12:45:14.078+0800:147098.890: [cms-concurrent-reset-start]2014-12-09t12:45:14.084+0800: 147098.896: [cms-concurrent-reset:0.006/0.006 secs] [times:user=0.00 sys=0.00, real=0.01 secs]

I marked the CMS initial mark and remark's log.

We can see that a total of two CMS has occurred, so the full GC should be 4 times

Full GC time = 0.07 secs (first time initial mark) + 0.23 secs (first remark) + 0.07 secs (second initial mark) + 0.20 secs (second remark) = 0.57s

The Times and times of the full GC are also consistent with JSTAT-GC.

So Jstat is the official Java tool, so we can conclude that it is consistent with the official.

Here's the visual GC, see old Gen Stats: 4 collections, 576.421ms

We can safely say:

1. Full GC = = Major GC refers to the old age/permanent generation of the Stop the World GC

2. Number of Full GC = number of Stop the world in the old age GC

3. Time of Full GC = The total time of the Stop the world in the old age GC

4. CMS is not equal to full GC, we can see the CMS is divided into several stages, only the Stop the world phase is calculated to the full GC number and time, and the business thread concurrent GC number and time is not considered to be full GC

We can see that the normal CMS stops the world for a short time, all at a level of dozens of to hundreds of MS, with little impact on full GC time. But sometimes the full GC we see with Jstat is a long time. For example, the following is the same application as Tomcat above, just before I tuned the data.

We see the evaluation time of the full GC before tuning = 1188/223 = 5 seconds, which means that the time of the Stop the world of a single full GC reaches 5s! To further analyze the log, get the following log:

54090.152: [Full GC (System) 54090.153: [cms:1211220k->1428569k (4096000K), 5.4936890 secs] 3483935k->1428569k ( 7168000K), [CMS perm:148045k->147921k (262144K)], 5.4963160 secs] [times:user=5.50 sys=0.00, real=5.50 secs] 57696.21 8: [Full GC (System) 57696.219: [cms:1513461k->1213731k (4096000K), 4.7293810 secs] 3283076k->1213731k (7168000K),  [CMS perm:148019k->147881k (262144K)], 4.7317730 secs] [times:user=4.73 sys=0.00, real=4.74 secs] 61301.483: [Full GC (System) 61301.484: [cms:1288630k->968887k (4096000K), 4.5720170 secs] 2466308k->968887k (7168000K), [CMS perm:14 7996k->147835k (262144K)], 4.5743720 secs] [times:user=4.57 sys=0.00, real=4.57 secs] 64906.588: [Full GC (System) 6490 6.590: [cms:1026456k->1568407k (4096000K), 5.0347600 secs] 3769961k->1568407k (7168000K), [CMS perm:148004k-> 147903K (262144K)], 5.0373410 secs] [times:user=5.02 sys=0.00, real=5.04 secs] 68512.160: [Full GC (System) 68512.161: [CM s:1631217k->838700k (4096000K),4.7239290 secs] 2552874k->838700k (7168000K), [CMS perm:148017k->147829k (262144K)], 4.7261610 secs] [times:user= 4.72 sys=0.00, real=4.72 secs] 72117.421: [Full GC (System) 72117.423: [Cms:905025k->1529502k (4096000K), 5.3562640 sec S] 3556285k->1529502k (7168000K), [CMS perm:148049k->147945k (262144K)], 5.3587790 secs] [times:user=5.36 sys=  0.00, real=5.36 secs]

We see the system.gc caused by the full GC, and the old age of GC time reached more than 5 seconds, it shows the CMS, but actually not the CMS concurrency collector, but the CMS occurred concurrent mode fail after the degenerate into the serial old collector , it is a single-threaded tag-compression collector, so it takes a very long time.

This article only focuses on data, not to discuss why the full GC before tuning to stop the world 5 seconds, and tuning after the full GC, only the normal implementation of the CMS, and the old age of Stop the world time to hundreds of Ms.

Finally, we emphasize the conclusion again:

1. Full GC = = Major GC refers to the old age/permanent generation of the Stop the World GC

2. Number of Full GC = number of Stop the world in the old age GC

3. Time of Full GC = The total time of the Stop the world in the old age GC

4. CMS is not equal to full GC, we can see the CMS is divided into several stages, only the Stop the world phase is calculated to the full GC number and time, and the business thread concurrent GC number and time is not considered to be full GC

5. The full GC itself does not first minor GC, we can configure, let the full GC before the minor GC, because many objects in the old age will refer to the new generation of objects, a first minor GC can increase the speed of the old GC. For example, the old age when using CMS, set Cmsscavengebeforeremark optimization, let the CMS remark before the first minor GC.

Talk about the JVM (iv) in-depth understanding major GC, full GC, CMS