GC日志说明.docxVIP

【转载】JAVA性能优化-GC日志分析2009-07-2218:02前两篇说到IBMJDK和Sun的HotSpotJDK的调优策略，当中一直提到的重要一点是需要根据GC详细日志来调整参数的设置，那么当我们收集到日志后如何分析，如何根据日志的情况来调整参数？这就是本文所要阐述的。使用IBM的JDK的Windows平台和AIX平台，我们只要在WebSphere管理控制台的java进程属性里勾选“详细垃圾回收”，那么就会在native_stdout.log中生成如下的信息。这幅图很形象的给出了gc日志的主要关注点：垃圾回收的原因、垃圾回收的间隔、垃圾回收前后的剩余空间、垃圾回收持续的时间……“nursery”表示这次分配失败（AllocationFailure）发生在新生代（nursery），是第44次（id=44）因为新生代的分配失败而进行垃圾回收了（开启GC日志以来），离上一次发生GC的间隔是12746ms，无法分配的空间大小是8216Byte，而进行垃圾回收前，新生代的可用空间为1776Byte，小于8216Byte，虽然年老区还剩余45%的空间，但是新的内存空间是无法直接在年老区分配的，由此引发了一次清理过程（scavenger）。GCtype表明了这次垃圾回收是一个清理过程，也是第44次scavenger过程，同时恰是第44个gc过程，说明没有发生过诸如gctype=”global”的垃圾回收过程。flippedobjectcount说明将要把4523143个存活下来的对象被复制到了幸存区（survivorspace），而73768个对象则经过多次幸存区的复制，有幸熬出头，被转移到了长存区（tenuredspace）。我们看到清理的倾斜比率（scavengertiltratio）为89%，而不是对半开，说明经过多次复制清理，JVM已经意识到每次只有很少的对象能存活下来，于是它自动增大了年轻代中Eden区的大小，以使得为新对象可以腾出更多的内存。接下来的就比较简单，经过垃圾回收，新生代的空间剩余89%，因为分配失败发生在新生代，进行的是快速的Minorgc，所以长存区的可用空间依然是45%，这次回收的时间为384.469ms。在长存区发生的是Majorgc，回收时间一般要长于Minorgc，所以健康的JVM环境Minorgc：Minorgc=1：10（也不用太在意）。在垃圾回收准备开始的那一段时间（timeexclusiveaccessms），以及回收的过程中，另一个线程发现内存无法分配了，于是也要求一次gc过程，这时候就产生了gc队列（会有warningdetails=”exclusiveaccesstimeincludespreviousgarbagecollections”/显示）。一般前一次垃圾回收就会释放出足够这两次分配需要的空间，于是第二次gc过程就终止了，当然要是无法足够分配的话，马上就会再进行一次垃圾回收。不过这种情况下，估计要进行FullGC了。FullGC的gctype就是global，这是stoptheworld的最耗费时间的回收方式，所以需要通过尽量调整参数来避免。如果发现不是由AF引起的，而是在开头写着SYS标签，那么就要好好问问开发，有没有使用System.gc()的必要？可以的话使用-Xdisableexplicitgc来禁止。以上所说的都是IBMJDK下垃圾回收日志的情况。在Sun和HP的JDK下情况相似，不过需要使用-XX:PrintHeapAtGC:参数来打印GC前后的详细堆栈信息。另外我建议加上-Xloggc:filename输出到特定文件，因为不知为何有时候会输出到native_stderr.log，或者在native_stdout.log中和threaddump夹杂在一起，不方便分析。{HeapbeforeGCinvocations=116:Heapdefnewgeneration  total157376K,used139904K6dec0000edenspace139904K,100%used6bca0000,6bca0000)fromspace17472K,  0%used[6bca0000,6bca0000,6cdb0000)to  space17472K,  0%used[6cdb0000,6cdb0000,6dec0000)tenuredgeneration  total349568K,used79067K4dd60000,632b0000)  thespace349568K,22%used3d536ce0,3d536e00,4dd60000)compact