《Java Performance The Definitive

前言

最近断断续续看了《Java Performance The Definitive Guide》前六章，记录一下关于GC部分的读书笔记。

GC

本书的第五章和第六章主要讲了关于GC相关的只是，由于目前线上机器多采用了CMS，所以重点关注CMS部分。先设置PrintGCDetails后，观察gc.log

Understanding the Throughput Collector

这种类型的GC会对Young和Old都进行STW型的收集

YGC

YGC的日志大概长这样

17.806: [GC [PSYoungGen: 227983K->14463K(264128K)]
280122K->66610K(613696K), 0.0169320 secs]
[Times: user=0.05 sys=0.00, real=0.02 secs]

该段日志表明本次gc发生在据程序开始运行12.806秒后（gclog的时间格式可以设置）。gc后，young区的对象占用了14MB内存空间（在survivor区）。在gc前，young区对象占用了227MB。目前young区的总大小为264MB。
同时，整个heap的占用（包括young区和old区）从280MB减少到227MB，目前整个heap的大小为613MB。整个gc操作共耗时0.02s。整个gc程序消耗的cpu时间比realtime（实际时间）要长，主要是因为ygc是由多个线程（本次配置为4个线程）共同完成的。

full gc

old区gc同时会清除young区的所有对象（包括survivor的对象）。Old区中仅剩的对象都有活跃引用，所有这些对象都会被压缩排列。

FUllGC的日志大概长这样

64.546: [Full GC [PSYoungGen: 15808K->0K(339456K)]
[ParOldGen: 457753K->392528K(554432K)] 473561K->392528K(893888K)
[PSPermGen: 56728K->56728K(115392K)], 1.3367080 secs]
[Times: user=4.44 sys=0.01, real=1.34 secs]

这段日志表明，现在Young区总共占用0bytes(总的大小为339MB)。old区中的数据从457MB减少到了392MB，因此整个heap使用从473MB减少到了392MB。permgen的大小没有改变，在大多数full gc时，permgen大小不会该表（如果permgen区占满了，JVM会触发一次fullgc进行permgc，此时permgen的占用大小才会改变）。因为full gc有更多工作需要做，所以花了1.3秒实际时间，4.4s的cpu时间（因为有四个并行线程）

总结

• throughput collector有两种操作：minor gc和full gc。
• gc Log中的时间可以用来衡量gc对于应用的影响

Understanding the CMS Collector

由于目前线上的机器大部分使用的是cms gc策略，所以重点关注了这部分

cms有三种基本的操作：

• cms进行ygc(将停止所有应用线程)
• cms开启concurrent cycle清除old区的数据
• 如果有必要，cms进行full gc

young gc

cms ygc和throughput的ygc非常相似：data从eden移入到一个survivor区中，然后进去old区。
cms的gc log和throughput的非常相似

89.853: [GC 89.853: [ParNew: 629120K->69888K(629120K), 0.1218970 secs]
1303940K->772142K(2027264K), 0.1220090 secs]
[Times: user=0.42 sys=0.02, real=0.12 secs]

日志表明：young区当下的大小为629MB，在gc后，占用了69MB（在survivor区）。类似的，整个Heap的大小为2027MB，在gc后，仍然有772MB被占用。整个过程花费了0.12s，耗费了0.42s的cpu时间。

concurrent cycle

根据heap的占用，jvm将开启concurrent cycle。当足够满的时候，jvm开启backgroup线程从heap中移除对象。需要注意的是Old区不会被压缩整理：已分配的区域和空闲区域可能间隔。当ygc后将对象从eden区移入到old区中，jvm将使用上述空闲区域容纳这些对象。

从gclog中可以看出，整个concurrent cycle 分成很多阶段。即使concurrent cycle的主要过程使用background线程，但是仍然有些阶段会导致短暂暂停所有应用线程。

initial mark phase

concurrent cycle开始于一个initial mark阶段，这个阶段暂停了所有的应用。日志如下：

89.976: [GC [1 CMS-initial-mark: 702254K(1398144K)]
772530K(2027264K), 0.0830120 secs]
[Times: user=0.08 sys=0.00, real=0.08 secs]

这个阶段主要是负责找出heap中所有的gc roots。第一组数字表示说目前old区的大小为1398MB，对象占用了702MB。第二组数字说明整个heap的大小为2027MB，对象占用了772MB。在在initial mark阶段，应用线程暂停了0.08s。

mark phase

接下来的就是mark 阶段，在这个阶段中不会暂停应用线程。gc日志中会出现以下行：

90.059: [CMS-concurrent-mark-start]
90.887: [CMS-concurrent-mark: 0.823/0.828 secs]
[Times: user=1.11 sys=0.00, real=0.83 secs]

mark阶段耗时0.83s(1.11秒的CPU时间)。由于只是进行mark，所以没有出现和heap内存占用相关的信息。

preclean phase

该阶段不会暂停应用线程

abortable-preclean phase

有了preclean phase为啥还需要abortable-preclean phase呢，abortable-preclean phase到底是做什么用的。
需要abortable-preclean阶段主要考量是因为remark phase阶段会需要STW（YGC也是需要STW的）。为了不让系统在ygc之后马上进行remark（因为这样会连续经历两次STW，时间拉长）
。所以abortable-preclean会在young区差不多50%满的时候开始。在ygc完成后，cms会根据之前的ygc时间计算下次ygc发生的时间，在预测young区差不多50%满的时候停止abortable-preclean，然后紧接着remark阶段开始。

同时，由于remark阶段会需要重新扫描young区，所以会存在一个矛盾。为了让remark更快，young区必须更小（最好是刚minor gc完）所以从remark时间最短的角度来看最好是每次remark之前都要触发一次minor gc（设置CMSScavengeBeforeRemark）。但是这样又会造成连续两次STW（minor gc & remark），造成系统不可用时间拉长。所以最好的解决方案就是为让ygc和remark之间通过abortable-preclean阶段隔开，并且会希望在abortable-preclean阶段过程中发生一次minor gc，所以在young区50%满的时候开始，在进行完一次monir gc，并且估算差不多又一次young区50%满的时候停止abortable-preclean（停止abortable-preclean不止取决于很多因素，通过CMSMaxAbortablePrecleanTime可以影响，超过CMSMaxAbortablePrecleanTime不管有没有发生minor gc都会进入到remark阶段，所以CMSMaxAbortablePrecleanTime应该和minor gc周期保持关系）

remark phase

紧接着就是remark phase阶段，日志如下：

90.892: [CMS-concurrent-abortable-preclean-start]
92.392: [GC 92.393: [ParNew: 629120K->69888K(629120K), 0.1289040 secs]

1331374K->803967K(2027264K), 0.1290200 secs]
[Times: user=0.44 sys=0.01, real=0.12 secs]
94.473: [CMS-concurrent-abortable-preclean: 3.451/3.581 secs]
[Times: user=5.03 sys=0.03, real=3.58 secs]
94.474: [GC[YG occupancy: 466937 K (629120 K)]
94.474: [Rescan (parallel) , 0.1850000 secs]
94.659: [weak refs processing, 0.0000370 secs]
94.659: [scrub string table, 0.0011530 secs]
[1 CMS-remark: 734079K(1398144K)]
1201017K(2027264K), 0.1863430 secs]
[Times: user=0.60 sys=0.01, real=0.18 secs]

上述日志包括了abortable-preclean和remark，通过abortable-preclean，使得minor gc和remark两个stw阶段之间差不多隔了半个minor gc周期。需要注意的是remark阶段会scan整个heap，注意日志中的94.474: [GC[YG occupancy: 466937 K (629120 K)]
94.474: [Rescan (parallel) , 0.1850000 secs]

sweep phase

接下来的一个阶段是concurrent sweep phase，这个阶段不会stw

94.661: [CMS-concurrent-sweep-start]
95.223: [GC 95.223: [ParNew: 629120K->69888K(629120K), 0.1322530 secs]
999428K->472094K(2027264K), 0.1323690 secs]
[Times: user=0.43 sys=0.00, real=0.13 secs]
95.474: [CMS-concurrent-sweep: 0.680/0.813 secs]
[Times: user=1.45 sys=0.00, real=0.82 secs]

这个阶段花费了大概0.82s。阶段中间还经历了一次minor gc。需要说明的是minor gc可能会同时出现在old collection phases。在整个the sweep phase阶段可能会出现任意多个minor gc。

reset phase

最后，是reset阶段

95.474: [CMS-concurrent-reset-start]
95.479: [CMS-concurrent-reset: 0.005/0.005 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]

至此，整个CMS cycle完成了。

CMS问题

concurrent mode failure

gc log会出现一些问题日志，表明cms遭遇了问题，首先就是‘concurrent mode failure’.

日志如下：

267.006: [GC 267.006: [ParNew: 629120K->629120K(629120K), 0.0000200 secs]
267.006: [CMS267.350: [CMS-concurrent-mark: 2.683/2.804 secs]
[Times: user=4.81 sys=0.02, real=2.80 secs]
(concurrent mode failure):
1378132K->1366755K(1398144K), 5.6213320 secs]
2007252K->1366755K(2027264K),
[CMS Perm : 57231K->57222K(95548K)], 5.6215150 secs]
[Times: user=5.63 sys=0.00, real=5.62 secs]

当minor gc发生了，但是old区中没有足够的空间容纳需要晋升的对象时，cms会触发一次full gc。此时STW，所有应用线程都会停止，old区中dead对象会被清理，上述日志中表明old区清理到了136MB，但是full gc STW了5.62s。这个操作是单线程进行的，所以花费了很长时间。

promotion failed

第二个问题就是当old区有足够的空间给待晋升的对象时，但是由于空闲内存过于碎片化导致的。

6043.903: [GC 6043.903:
[ParNew (promotion failed): 614254K->629120K(629120K), 0.1619839 secs]
6044.217: [CMS: 1342523K->1336533K(2027264K), 30.7884210 secs]
2004251K->1336533K(1398144K),
[CMS Perm : 57231K->57231K(95548K)], 28.1361340 secs]
[Times: user=28.13 sys=0.38, real=28.13 secs]

日志表明，cms开始了一次ygc，而且认为old区中有足够的空间来容纳待晋升的对象（否则，将会导致concurrent mode failure问题），然后由于old区内存过于碎片化，导致cms无法晋升这些对象。

所以，在minor gc的过程中，cms尝试去清理和压缩整理old区。好消息是heap最终会被重新压缩整理，碎片化问题得以解决。但是会带来一个28秒的停顿时间。这个时间比发生‘concurrent mode failure’时消耗的时间要长，因为此时整个heap进行了压缩整理，而concurrent mode failure只free掉old区的内存。

permgen fill up

当perm区满了之后，需要被回收，会触发一次Full gc

279.803: [Full GC 279.803:
[CMS: 88569K->68870K(1398144K), 0.6714090 secs]
558070K->68870K(2027264K),
[CMS Perm : 81919K->77654K(81920K)],
0.6716570 secs]

CMS问题解决手段(Tuning to Solve Concurrent Mode Failures)

concurrent mode or promotion failures产生的原因其实是由于‘老年代cms cycle和minor gc速度的不匹配’。

The old generation initially fills up by placing the objects right next to each other. When
some amount of the old generation is filled (by default, 70%), the concurrent cycle begins
and the background CMS thread(s) start scanning the old generation for garbage. At
this point, a race is on: CMS must complete scanning the old generation and freeing
objects before the remainder (30%) of the old generation fills up. If the concurrent cycle
loses the race, CMS will experience a concurrent mode failure.

可以从以下多个方面来避免：

• 加大old区，要不就是加大old区的比重，要不就是跳大heap 空间。
• 使得cms cycles更频繁
• 使用更多的background 线程

Running the background thread more often

要想让CMS赢得‘比赛’需要使得concurrent cycle更早的执行。
我们可以通过设置-XX:CMSInitiatingOccupancyFraction=N 和 -XX:+UseCMSInitiatingOccupancyOnly改变开始执行的计算逻辑。默认的UseCMSInitiatingOccupancyOnly是false，CMS会用一个很复杂的算法决定什么时候来时concurrent cycle.
当UseCMSInitiatingOccupancyOnly设置为true时，默认的XX:CMSInitiatingOccupancyFraction是70，也就是说在old区70%被占满的时候开始concurrent cycle。

Adjusting the CMS background threads

Each CMS background thread will consume 100% of a CPU on a machine.cms gc后台线程的数量可以通过-XX:ConcGCThreads=N设置。默认的话，
ConcGCThreads = (3 + ParallelGCThreads) / 4

总结

1. Avoiding concurrent mode failures is the key to achieving the
   best possible performance with CMS.

2. The simplest way to avoid those failures (when possible) is to
   increase the size of the heap.
3. Otherwise, the next step is to start the concurrent background
   threads sooner by adjusting the CMSInitiatingOccupancyFrac
   tion.
4. Tuning the number of background threads can also help.

监控手段

• 最直接的监控手段就是通过详细的gc.log，我们可以通过脚本抓取并分析gc.log，可以通过关键词检测有无‘concurrent mode failures’和‘promotion failed’，有无‘Fullgc’等，原则上有这些关键字存在需要立即触发warning报警。
• 分析日志可以得出ygc的频率和时长，ygc频率过高，平均时间拉长到阈值应该触发报警
• 可以通过GarbageCollectorMBean获取collectCount和collectTime，需要注意的是Count是累加总次数，collectTime是累加的STW的总时间

总结

java performance GC相关读书笔记，看到新的东西会继续补充