1、前两篇说到 IBM JDK 和 Sun 的 HotSpot JDK 的调优策略，当中一直提到的重要一点是需要根据GC 详细日志来调整参数的设置，那么当我们收集到日志后如何分析，如何根据日志的情况来调整参数？这就是本文所要阐述的。使用 IBM 的 JDK 的 Windows 平台和 AIX 平台，我们只要在 WebSphere 管理控制台的 java 进程属性里勾选“详细垃圾回收” ，那么就会在 native_stdout.log 中生成如下的信息。这幅图很形象的给出了 gc 日志的主要关注点：垃圾回收的原因、垃圾回收的间隔、垃圾回收前后的剩余空间、垃圾回收持续的时间“nursery”表示这次分
2、配失败（Allocation Failure）发生在新生代（nursery），是第 44 次（id=44 ）因为新生代的分配失败而进行垃圾回收了（开启 GC 日志以来），离上一次发生 GC 的间隔是12746ms，无法分配的空间大小是 8216Byte，而进行垃圾回收前，新生代的可用空间为 1776Byte，小于 8216Byte，虽然年老区还剩余 45%的空间，但是新的内存空间是无法直接在年老区分配的，由此引发了一次清理过程（scavenger）。GC type 表明了这次垃圾回收是一个清理过程，也是第 44 次 scavenger 过程，同时恰是第 44个 gc 过程，说明没有发生过诸如
3、的垃圾回收过程。flipped objectcount 说明将要把 4523143 个存活下来的对象被复制到了幸存区（survivor space），而 73768 个对象则经过多次幸存区的复制，有幸熬出头，被转移到了长存区（tenured space）。我们看到清理的倾斜比率（scavenger tiltratio）为 89%，而不是对半开，说明经过多次复制清理，JVM 已经意识到每次只有很少的对象能存活下来，于是它自动增大了年轻代中 Eden 区的大小，以使得为新对象可以腾出更多的内存。接下来的就比较简单，经过垃圾回收，新生代的空间剩余 89%，因为分配失败发生在新生代，进行的是快速的 M
4、inor gc，所以长存区的可用空间依然是 45%，这次回收的时间为 384.469ms。在长存区发生的是 Major gc，回收时间一般要长于 Minor gc，所以健康的 JVM 环境 Minor gc：Minor gc=1：10（也不用太在意）。在垃圾回收准备开始的那一段时间（time exclusiveaccessms），以及回收的过程中，另一个线程发现内存无法分配了，于是也要求一次 gc 过程，这时候就产生了 gc 队列（会有显示）。一般前一次垃圾回收就会释放出足够这两次分配需要的空间，于是第二次 gc 过程就终止了，当然要是无法足够分配的话，马上就会再进行一次垃圾回收。不过这种情况
5、下，估计要进行 Full GC 了。Full GC 的 gc type 就是 global，这是 stop the world 的最耗费时间的回收方式，所以需要通过尽量调整参数来避免。如果发现不是由 AF 引起的，而是在开头写着 SYS 标签，那么就要好好问问开发，有没有使用 System.gc()的必要？可以的话使用-Xdisableexplicitgc 来禁止。以上所说的都是 IBM JDK 下垃圾回收日志的情况。在 Sun 和 HP 的 JDK 下情况相似，不过需要使用-XX:PrintHeapAtGC: 参数来打印 GC 前后的详细堆栈信息。另外我建议加上-Xloggc:filenam
6、e或者-Xverbosegclog:file_name（方便用工具分析）输出到特定文件，因为不知为何有时候会输出到 native_stderr.log，或者在 native_stdout.log 中和 thread dump 夹杂在一起，不方便分析。Heap before GC invocations=116:Heapdef new generation total 157376K, used 139904K 63400000, 6dec0000, 78950000)eden space 139904K, 100% used 63400000, 6bca0000, 6bca0000)from
7、space 17472K, 0% used 6bca0000, 6bca0000, 6cdb0000)to space 17472K, 0% used 6cdb0000, 6cdb0000, 6dec0000)tenured generation total 349568K, used 79067K 38800000, 4dd60000, 632b0000)the space 349568K, 22% used 38800000, 3d536ce0, 3d536e00, 4dd60000)compacting perm gen total 132096K, used 132023K 28800
8、000, 30900000, 38800000)the space 132096K, 99% used 28800000, 308edf50, 308ee000, 30900000)GC 218971K-83116K(506944K), 0.0976948 secsHeap after GC invocations=117:Heapdef new generation total 157376K, used 4049K 63400000, 6dec0000, 78950000)eden space 139904K, 0% used 63400000, 63400000, 6bca0000)fr
9、om space 17472K, 23% used 6cdb0000, 6d1a4628, 6dec0000)to space 17472K, 0% used 6bca0000, 6bca0000, 6cdb0000)tenured generation total 349568K, used 79067K 38800000, 4dd60000, 632b0000)the space 349568K, 22% used 38800000, 3d536ce0, 3d536e00, 4dd60000)compacting perm gen total 132096K, used 132023K 28800000, 30900000, 38800000)the space 132096K, 99% used 28800000, 308edf50, 308ee000, 30900000)这是一个在使用 HPJDK 输出的实例，基本和 IBM JDK 没啥区别，可以加上 -XX:+PrintGCTimeStamps 显示每次回收的间隔。
