jvm垃圾回收——诊断垃圾收集问题

http://www.oracle.com/technetwork/java/example-141412.html

转载请注明出处，多谢。
这个附录包含说明垃圾收集问题的日志的例子。如不指定，使用默认收集器。除非另有说明，日志依据下面生成：
-verbosegc -XX:+ PrintGCDetails
这个输出格式用于1.4.3。这个格式在以后的版本不保证不变。尤其和-XX:+ PrintGCDetail相关的的输出，几乎不保证不变，这些输出代表了JVM开发者的当前需要。
这些选项的次要收集输出：
[GC [<collector>: <starting occupancy1> -> <ending occupancy1>, <pause time1> secs] <starting occupancy3> -> <ending occupancy3>, <pause time3> secs]
其中：
<collector>                   次要收集使用的收集器的内部名字。
<starting occupancy1>       收集之前年轻代的占用。（译者：1个伊甸园+1个生还者）
<ending occupancy1> 收集之后年轻代的占用。
<pause time1>           次要gc的暂停时间的秒数。
<starting occupancy3>       收集之前整个堆占用（1个伊甸园+1个生还者+1个老年代）。
<ending occupancy3> 收集之后整个堆占用。
<pause time3>            整个堆收集的暂停时间。包括完成主GC时间。
 
在这，下面的日志片段是列出的收集信息的例子。如果陈述是关于一个量，像暂停时间、引用的数量是收集的数据集的总汇的平均值，不只来自于提供的日志片段。如果给了范围值，这个范围来自提供的日志片段。

1 年轻代太小

第一个例子的堆大小是32M，年轻代的大小是4M：
[GC [DefNew: 4032K->64K(4032K), 0.0429742 secs] 9350K->7748K(32704K), 0.0431096 secs]
[GC [DefNew: 4032K->64K(4032K), 0.0403446 secs] 11716K->10121K(32704K), 0.0404867 secs]
[GC [DefNew: 4032K->64K(4032K), 0.0443969 secs] 14089K->12562K(32704K), 0.0445251 secs]
       这个输出从垃圾时间消耗的角度看，是合理的。但是注意，年轻代的占用减少（第一行，从4032k到64k，共3968k），整个堆的占用减少的更少（从9350k到7748k，共1602k）。这说明年轻代40%是垃圾，其余的对象在收集中生还，被提升到老年代。

1.1 收集之后增加年轻代大小，以增加可用空间

年轻代被增加到8M：
[GC [DefNew: 8128K->64K(8128K), 0.0453670 secs] 13000K->7427K(32704K), 0.0454906 secs]
[GC [DefNew: 8128K->64K(8128K), 0.0388632 secs] 15491K->9663K(32704K), 0.0390013 secs]
[GC [DefNew: 8128K->64K(8128K), 0.0388610 secs] 17727K->11829K(32704K), 0.0389919 secs]
8M的年轻代，在次GC中大多数是垃圾。在第一行，年轻代从8128k到64k减少了8064k，整个堆从13000k到7427k减少5573k，意味着年轻代的68%是垃圾。正如所料，年轻代的大小没有改变次要GC生还的活对象的数量（大于2.4M），但是减少了次GC次数和次GC暂停时间（每行最后的时间）。

1.2 应用时间和停止时间

       为了对比4M年轻代和8M年轻代的消耗，下面是附带命令行-XX:+ PrintGCApplicationConcurrentTime和-XX:+ PrintGCApplicationStoppedTime的输出，它测量了收集之间的时间和收集时间。4M年轻代情况下，应用运行时间.53到.91秒，次要GC暂停时间.045到.047秒。大约5%到8%的次GC开销。
Application time: 0.5291524 seconds
[GC [DefNew: 3968K->64K(4032K), 0.0460948 secs] 7451K->6186K(32704K), 0.0462350 secs]
Total time for which application threads were stopped: 0.0468229 seconds
Application time: 0.5279058 seconds
[GC [DefNew: 4032K->64K(4032K), 0.0447854 secs] 10154K->8648K(32704K), 0.0449156 secs]
Total time for which application threads were stopped: 0.0453124 seconds
Application time: 0.9063706 seconds
[GC [DefNew: 4032K->64K(4032K), 0.0464574 secs] 12616K->11187K(32704K), 0.0465921 secs]
Total time for which application threads were stopped: 0.0470484 seconds
8M年轻GC：
Application time: 1.3874623 seconds
[GC [DefNew: 8064K->63K(8128K), 0.0509215 secs] 11106K->5994K(32704K), 0.0510972 secs]
Total time for which application threads were stopped: 0.0517092 seconds
Application time: 1.5225065 seconds
[GC [DefNew: 8127K->63K(8128K), 0.0432982 secs] 14058K->8273K(32704K), 0.0434172 secs]
Total time for which application threads were stopped: 0.0440447 seconds
Application time: 1.4263524 seconds
[GC [DefNew: 8127K->64K(8128K), 0.0363538 secs] 16337K->10381K(32704K), 0.0364811 secs]
Total time for which application threads were stopped: 0.0369103 seconds
       应用运行1.38到1.52秒之间，收集暂停.036到.051秒。大约2.6到3.6%的次GC开销。

2 年轻代太大

年轻代从4M到8M，次GC的开销减少一半。如果年轻代增加到16M会怎样？
[GC [DefNew: 16000K->16000K(16192K), 0.0000574 secs][Tenured: 2973K->2704K(16384K), 0.1012650 secs] 18973K->2704K(32576K), 0.1015066 secs]
[GC [DefNew: 16000K->16000K(16192K), 0.0000518 secs][Tenured: 2704K->2535K(16384K), 0.0931034 secs] 18704K->2535K(32576K), 0.0933519 secs]
[GC [DefNew: 16000K->16000K(16192K), 0.0000498 secs][Tenured: 2535K->2319K(16384K), 0.0860925 secs] 18535K->2319K(32576K), 0.0863350 secs]
这个例子，年轻代相对老年代太大，而不允许年轻代提升被担保（年轻代大约是老年代的一半）。年轻代不能被成功收集，只有主GC发生。注意，在这，年轻代被收集了，但是只是更昂贵的主GC的一部分。

3 老年代太大或者太小？

8M的年轻代，整个堆32M，主GC暂停大约.13秒:
[GC [DefNew: 8128K->8128K(8128K), 0.0000558 secs]
f970
[Tenured: 17746K->2309K(24576K), 0.1247669 secs] 25874K->2309K(32704K), 0.1250098 secs]
如果堆大小增加到64M，主GC暂停大于.21秒:
[GC [DefNew: 8128K->8128K(8128K), 0.0000369 secs][Tenured: 50059K->5338K(57344K), 0.2218912 secs] 58187K->5338K(65472K), 0.2221317 secs]
但是主GC频率下降一半。通过添加-XX:+ PrintGCTimeStamps看收集输出的时间戳。32M堆的主GC大约10-11秒一次（只显示主GC）:
111.042: [GC 111.042: [DefNew: 8128K->8128K(8128K), 0.0000505 secs]111.042: [Tenured: 18154K->2311K(24576K), 0.1290354 secs] 26282K->2311K(32704K), 0.1293306 secs]
122.463: [GC 122.463: [DefNew: 8128K->8128K(8128K), 0.0000560 secs]122.463: [Tenured: 18630K->2366K(24576K), 0.1322560 secs] 26758K->2366K(32704K), 0.1325284 secs]
133.896: [GC 133.897: [DefNew: 8128K->8128K(8128K), 0.0000443 secs]133.897: [Tenured: 18240K->2573K(24576K), 0.1340199 secs] 26368K->2573K(32704K), 0.1343218 secs]
144.112: [GC 144.112: [DefNew: 8128K->8128K(8128K), 0.0000544 secs]144.112: [Tenured: 16564K->2304K(24576K), 0.1246831 secs] 24692K->2304K(32704K), 0.1249602 secs]
64M堆的主GC大约30秒一次:
90.597: [GC 90.597: [DefNew: 8128K->8128K(8128K), 0.0000542 secs]90.597: [Tenured: 49841K->5141K(57344K), 0.2129882 secs] 57969K->5141K(65472K), 0.2133274 secs]
120.899: [GC 120.899: [DefNew: 8128K->8128K(8128K), 0.0000550 secs]120.899: [Tenured: 50384K->2430K(57344K), 0.2216590 secs] 58512K->2430K(65472K), 0.2219384 secs]
153.968: [GC 153.968: [DefNew: 8128K->8128K(8128K), 0.0000511 secs]153.968: [Tenured: 51164K->2309K(57344K), 0.2193906 secs] 59292K->2309K(65472K), 0.2196372 secs]
32M还是64M更好呢？吞吐量64M更好，32M的暂停时间更小。

3.1 更大的年轻代

为了追求更高吞吐量，考虑更大的堆。256M堆64M年轻代，相对于32M堆8M年轻代，次GC暂停多了10%；说明了从收集中生还的对象数大致相同。主GC多了3.8秒，说明了堆更大了。
[GC [DefNew: 64575K->959K(64576K), 0.0457646 secs] 196016K->133633K(261184K), 0.0459067 secs]
[GC [DefNew: 64575K->64575K(64576K), 0.0000573 secs][Tenured: 132673K->5437K(196608K), 0.4959855 secs] 197249K->5437K(261184K), 0.4962533 secs]
[GC [DefNew: 63616K->959K(64576K), 0.0360258 secs] 69053K->7600K(261184K), 0.0361663 secs]

4 调节之后，次GC暂停太长

4.1 尝试平行年轻代收集器

如果次GC暂停太长，尝试使用平行年轻代收集器。加上-XX:+UseParallelGC产生下面输出。在这个例子，为了简单，用-XX:- UseAdaptiveSizing关闭自适应调整大小。为了和上面对比也加了时间戳选项。
500.285: [GC 51526K->2678K(253952K), 0.0120328 secs]
506.734: [GC 51830K->2646K(253952K), 0.0117832 secs]
513.068: [GC 51798K->2742K(253952K), 0.0124632 secs]
519.566: [GC 51894K->2550K(253952K), 0.0122923 secs]
这里，平均次GC暂停大约0.15秒，减少了68%。关闭了自适应调整大小，因为加上之后，下面一组输出中会出现不寻常行为：
[GC 62752K->2992K(259328K), 0.0126936 secs]
[GC 62896K->60192K(259328K), 0.0127579 secs]
[GC 63008K->3120K(259328K), 0.0123150 secs]
[GC 63024K->60256K(259328K), 0.0120565 secs]
[GC 63072K->3024K(259328K), 0.0127215 secs]
[GC 62928K->60208K(259328K), 0.0113090 secs]
[GC 63024K->3136K(259328K), 0.0133799 secs]
[GC 63040K->60256K(259328K), 0.0135459 secs]
自适应调整生还者区大小。上面的日志展示的次要GC，生还者区的大小在来回变化，引起最小年轻代收集或者完整年轻代收集。虽然使用自适应调整的行为奇怪，但是仍然产生了高的吞吐量。

4.2 或者，使用-XX:+UseParNewGC收益

497.905: [GC 497.905: [ ParNew: 64576K->960K(64576K), 0.0255372 secs] 155310K->93003K(261184K), 0.0256767 secs]
506.305: [GC 506.305: [ParNew: 64576K->960K(64576K), 0.0276291 secs] 156619K->94267K(261184K), 0.0277958 secs]
514.565: [GC 514.565: [ParNew: 64576K->960K(64576K), 0.0261376 secs] 157883K->95711K(261184K), 0.0262927 secs]
522.838: [GC 522.838: [ParNew: 64576K->960K(64576K), 0.0316625 secs] 159327K->97331K(261184K), 0.0318099 secs]
显示了，次GC暂停大约减少44%。时间戳显示次GC执行周期。使用了-XX:+UseParallelGC之后，大约6.5秒执行一次，每次执行.015秒（次要GC开销大约0.33%）。使用-XX:+UseParNewGC之后，大约8秒一次，每次执行0.026秒（次要GC开销大约0.23%）。

5 调整之后，主GC太长

5.1 尝试并发低暂停收集器

主GC暂停在256M堆、64M年轻代下大约0.489秒。如果太长，尝试添加-XX:+UseConcMarkSweepGC（同时也设置-XX:+UseParNewGC）。
[GC [ParNew: 64576K->960K(64576K), 0.0377639 secs] 140122K->78078K(261184K), 0.0379598 secs]
[GC [ParNew: 64576K->960K(64576K), 0.0329313 secs] 141694K->79533K(261184K), 0.0331324 secs]
[GC [ParNew: 64576K->960K(64576K), 0.0413880 secs] 143149K->81128K(261184K), 0.0416101 secs]
[GC [1 CMS-initial-mark: 80168K(196608K)] 81144K(261184K), 0.0059036 secs]
[CMS-concurrent-mark: 0.129/0.129 secs]
[CMS-concurrent-preclean: 0.007/0.007 secs]
[GC[ Rescan (non-parallel) [ grey object rescan, 0.0020879 secs][root rescan, 0.0144199 secs], 0.0166258 secs][weak refs processing, 0.0000411 secs] [1 CMS-remark:80168K(196608K)] 82493K(261184K), 0.0168943 secs]
[CMS-concurrent-sweep: 1.208/1.208 secs]
[CMS-concurrent-reset: 0.036/0.036 secs]
[GC [ParNew: 64576K->960K(64576K), 0.0311520 secs] 66308K->4171K(261184K), 0.0313513 secs]
[GC [ParNew: 64576K->960K(64576K), 0.0348341 secs] 67787K->5695K(261184K), 0.0350776 secs]
[GC [ParNew: 64576K->960K(64576K), 0.0359806 secs] 69311K->7154K(261184K), 0.0362064 secs]
用于例子的应用，次GC执行间相对并发收集执行时间隔时间短。这个不是典型情况。更经常的情况，并发收集之间会有次要收集。注意，并发阶段可能比较长（例如，CMS-concurrent-sweep 是1.2秒）但是在并发阶段，应用并没有暂停，所以应用不会出现暂停。相反，虽然并发阶段应用没有暂停，但应用并没有使用全部处理器（其中一个被垃圾收集线程使用）。暂停来自于CMS-initial-mark和CMS-remark pause。在这个输出片段，较大的那些是017秒。CMS-remark pause的平均运行时间（最长的暂停）是0.019秒。主GC的最大暂停（和默认比较）从0.489秒减少到0.019秒（减少了96%）。也要注意，次GC暂停增加到0.035秒，大于只使用-XX:+UseParNewGC的0.026秒。这暗示了并发收集和主GC有关。

5.2 尝试增量地暂停收集器

主GC时间还可以通过增量低暂停收集器来减少。使用命令-Xincgc
[GC [DefNew: 64575K->959K(64576K), 0.0616204 secs][Train: 5537K->5474K(196608K), 0.0108803 secs] 68664K->6434K(261184K), 0.0730248 secs]
[GC [DefNew: 64575K->959K(64576K), 0.0559078 secs][Train: 6813K->6749K(196608K), 0.0115077 secs] 70050K->7709K(261184K), 0.0680289 secs]
[GC [DefNew: 64575K->959K(64576K), 0.0607615 secs][Train: 8178K->8114K(196608K), 0.0112705 secs] 71325K->9074K(261184K), 0.0727902 secs]
在执行每个次GC时，部分老年代被收集，没有单独的主GC暂停。次GC暂停时间增加到0.078秒。如果老年代增量收集，在老年代满之前不能完成，触发主GC，在日志中用MSC标示。
[GC [DefNew: 64575K->64575K(64576K), 0.0005311 secs][Train MSC: 68226K->135K(196608K), 0.4347857 secs] 132802K->2565K(261184K), 0.4397831 secs]
 
 
草稿版本：2003-2-20