jvm 的GC日志初体验

jvm 的GC日志初体验
关于GC的一些参数
-verbose.gc开关可显示GC的操作内容。打开它，可以显示最忙和最空闲收集行为发生的时间、收集前后的内存大小、收集需要的时间等。打开-xx:+ printgcdetails开关，可以详细了解GC中的变化。打开-XX: + PrintGCTimeStamps开关，可以了解这些垃圾收集发生的时间，自JVM启动以后以秒计量。最后，通过-xx: + PrintHeapAtGC开关了解堆的更详细的信息。为了了解新域的情况，可以通过-XX:=PrintTenuringDistribution开关了解获得使用期的对象权。

启动weblogic服务器之后，初始产生日志
0.000: [Full GC 0.000: [Tenured: 0K->4260K(1023104K), 0.1055162 secs] 30082K->4260K(1138240K), 0.1057452 secs]
4.628: [Full GC 4.628: [Tenured: 4260K->6546K(1023104K), 0.1354001 secs] 39901K->6546K(1138240K), 0.1356303 secs]
6.176: [Full GC 6.176: [Tenured: 6546K->7961K(1023104K), 0.1651181 secs] 21755K->7961K(1138240K), 0.1653515 secs]
12.859: [Full GC 12.859: [Tenured: 7961K->12270K(1023104K), 0.2777087 secs] 47887K->12270K(1138240K), 0.2779328 secs]
17.641: [GC 17.641: [DefNew: 102397K->3032K(115136K), 0.0495016 secs] 114668K->15303K(1138240K), 0.0497269 secs]
28.348: [Full GC 28.348: [Tenured: 12270K->15435K(1023104K), 0.2675010 secs] 75659K->15435K(1138240K), 0.2677256 secs]
40.499: [GC 40.499: [DefNew: 102399K->12736K(115136K), 0.3827322 secs] 117835K->45861K(1138240K), 0.3831325 secs]
48.871: [GC 48.871: [DefNew: 115136K->12736K(115136K), 0.5656438 secs] 148261K->85635K(1138240K), 0.5657204 secs]
56.585: [GC 56.585: [DefNew: 115135K->12736K(115136K), 0.4458067 secs] 188035K->118444K(1138240K), 0.4458949 secs]
66.213: [GC 66.213: [DefNew: 115135K->12736K(115136K), 0.3692542 secs] 220844K->144890K(1138240K), 0.3693315 secs]
76.251: [GC 76.251: [DefNew: 115135K->12735K(115136K), 0.2650355 secs] 247289K->174145K(1138240K), 0.2651241 secs]
82.396: [GC 82.397: [DefNew: 115135K->12735K(115136K), 0.1989967 secs] 276545K->217355K(1138240K), 0.1990755 secs]
89.504: [GC 89.504: [DefNew: 115135K->12735K(115136K), 0.2733299 secs] 319755K->291353K(1138240K), 0.2734123 secs]
95.257: [GC 95.258: [DefNew: 115135K->12736K(115136K), 0.3487282 secs] 399385K->340864K(1138240K), 0.3488096 secs]
98.271: [GC 98.271: [DefNew: 115135K->12735K(115136K), 0.4132144 secs] 443264K->388184K(1138240K), 0.4132912 secs]
101.577: [GC 101.577: [DefNew: 115135K->12736K(115136K), 0.5328404 secs] 513112K->470981K(1138240K), 0.5329206 secs]
105.371: [GC 105.371: [DefNew: 115135K->12736K(115136K), 0.6153580 secs] 573381K->532211K(1138240K), 0.6154395 secs]
182.208: [GC 182.208: [DefNew: 115136K->12736K(115136K), 0.4843296 secs] 634611K->564985K(1138240K), 0.4844138 secs]
191.752: [GC 191.752: [DefNew: 115135K->12735K(115136K), 0.5217968 secs] 667385K->603813K(1138240K), 0.5218681 secs]
201.570: [GC 201.570: [DefNew: 115135K->12735K(115136K), 0.4042610 secs] 706213K->638724K(1138240K), 0.4043473 secs]
211.013: [GC 211.013: [DefNew: 115135K->12736K(115136K), 0.3656211 secs] 741123K->668281K(1138240K), 0.3656906 secs]
223.204: [GC 223.204: [DefNew: 115136K->12736K(115136K), 0.2736965 secs] 770681K->690113K(1138240K), 0.2737970 secs]
228.496: [GC 228.496: [DefNew: 115135K->12735K(115136K), 0.2129989 secs] 792513K->733502K(1138240K), 0.2130814 secs]
236.952: [GC 236.952: [DefNew: 115134K->12736K(115136K), 0.2766950 secs] 858428K->814409K(1138240K), 0.2767798 secs]
做了一个大数据量查询后日志增加
588.865: [GC 588.865: [DefNew: 115135K->12736K(115136K), 0.0928617 secs] 916809K->824497K(1138240K), 0.0929371 secs]
725.903: [GC 725.903: [DefNew: 115135K->12736K(115136K), 0.1385650 secs] 926897K->837837K(1138240K), 0.1386372 secs]
736.062: [GC 736.062: [DefNew: 115136K->12736K(115136K), 0.3076112 secs] 940237K->860163K(1138240K), 0.3076883 secs]
750.298: [GC 750.298: [DefNew: 115135K->12736K(115136K), 0.2565046 secs] 962563K->882354K(1138240K), 0.2565766 secs]
758.875: [GC 758.875: [DefNew: 115135K->12736K(115136K), 0.2601905 secs] 984754K->904344K(1138240K), 0.2602707 secs]
764.257: [GC 764.258: [DefNew: 115135K->12736K(115136K), 0.2654858 secs] 1006744K->926708K(1138240K), 0.2655555 secs]
769.393: [GC 769.393: [DefNew: 115135K->115135K(115136K), 0.0000126 secs]769.393: [Tenured: 913972K->413259K(1023104K), 2.8389837 secs] 1029108K->413259K(1138240K), 2.8391320 secs]
对于DefNew和Tenured目前还不是很明白，根据字面意思理解，Tenured为系统占用，DefNew为动态增加。
时间点   [GC开始时间:[动态分配:初始值->分配值(可用值) ,  消耗时间     ] 初始值->回收后占用值(可用值),消耗时间]
764.257: [GC 764.258: [DefNew: 115135K->12736K(115136K), 0.2654858 secs] 1006744K->926708K(1138240K), 0.265555

本文来自CSDN博客，转载请标明出处：http://blog.csdn.net/zjwy82/archive/2005/06/02/386560.aspx

一、GC监控

GC日志记录了内存使用和回收状态，出现内存故障时，可作为分析排查手段。

1. 启用GC监控的方法：增加java启动参数-verbose:gc，输出信息的样例：

GC 135: total final references 4390; cleared final references 8.
GC 135: total phantom references 0; cleared phantom references 0.
GC 135: total old soft references 0; cleared old soft references 0.
GC 135: total JNI global weak references 0; cleared JNI global weak references 0.
GC 136: starting collection, maximum allocation reached.
GC 136: live objects 1081046; collected objects 6038; collected(KB) 558.
GC 136: queued for finalization 0; total soft references 113; cleared soft references 18.
GC 136: current heap(KB) 716784; current threshold(KB) 262144.
GC 136: collect (milliseconds) 1314.
GC 136: current cycle allocation(KB) 0; previous cycle allocation(KB) 532.
GC 136: total weak references 1321; cleared weak references 0.
2. 将GC日志输出到文件：不同JDK设置的参数不同，参考JDK官方文档
SUN：-Xloggc:filename （例如：-Xloggc:D:/gc.log）
IBM：-Xverbosegc:file=filename 或 -Xverbosegclog:filename
HP ：-Xverbosegc=filename

3. 如何设置Java启动参数：有多种方式，以下各举一例
Tomcat：在catalina.bat的“set JAVA_OPTS=%JAVA_OPTS% ”后设置
WebLogic：在startWebLogic.cmd的“%JAVA_HOME%\bin\java %JAVA_VM% %MEM_ARGS% %JAVA_OPTIONS% ”后设置
WebSphere：进入管理控制台，应用服务器->进程定义->Java虚拟机高级定义

4. GC日志的图形分析工具：HP的jtune

二、内存问题描述

典型现象是系统运行一段时间后，报OutOfMemoryError错误、页面非常慢、不响应或完全不再接受请求，而此时通过观察JVM内存，发现内存急剧上升到最大值并居高不下。

这种问题出现后，往往很棘手，通常是由于应用程序不合理造成的，而不合理程序或内存泄漏的源头可能并不明显。本人的一次经历是，经过十多天各种测试手段后，最后确定问题是由一处String累加引起的，改成StringBuffer就解决了，可见，忽略“小问题”往往会带来大麻烦。

三、分析手段

1. 分析GC日志、系统日志
2. 程序中设置监控断点
3. 尽可能重现故障并同时监控JVM内存，找出引起内存急剧上升的规律
4. 检查关键程序或频繁使用的工具类的合理性

四、解决手段

1. 主要从程序入手：降低内存使用量；字符串累加时以StringBuffer代替String；随时释放不再需要的对象；SQL优化及避免频繁取出大量数据；Session中不要放大的数据。。。
2. 据WebSphere和WebLogic官方建议：通常情况下JVM的Heap最小值和最大值可设成一样（根据实际情况调整），可取系统内存的25%-75%，保证JVM有合理足够的内存大小
3. 应用服务器的其他优化措施

五、应急措施

1. 不设定JVM的最大Heap上限
2. 程序中判断内存吃紧时执行Runtime.gc()强制垃圾收集，此方式比自动收集彻底，可一定程度上改善内存利用效率
3. 在不影响业务的情况下，定期重启应用服务器

jboss内存查看：
1. 用浏览器打开网址：http://IP:port/jmx-console/
2. 找到 jboss.system 一节,或者在 filter 文本框中输入 jboss.system 然后按下 ApplyFilter 按钮
3. 找到 type=ServerInfo 节点并点击进入
4. 找到 listMemoryPools() 方法，点击其下的 Invoke 按钮

一、java.lang.OutOfMemoryError: PermGen space
PermGen space的全称是Permanent Generation space,是指内存的永久保存区域,
这块内存主要是被JVM存放Class和Meta信息的,Class在被Loader时就会被放到PermGen space中,
它和存放类实例(Instance)的Heap区域不同,GC(Garbage Collection)不会在主程序运行期对
PermGen space进行清理，所以如果你的应用中有很多CLASS的话,就很可能出现PermGen space错误,
这种错误常见在web服务器对JSP进行pre compile的时候。如果你的WEB APP下都用了大量的第三方jar, 其大小
超过了jvm默认的大小(4M)那么就会产生此错误信息了。
解决方法： 手动设置MaxPermSize大小
JAVA_OPTS=”-server -XX:PermSize=64M -XX:MaxPermSize=128m
建议：将相同的第三方jar文件移置到server/all/lib目录下，这样可以达到减少jar 文档重复占用内存的目的。
二、java.lang.OutOfMemoryError: Java heap space
Heap size 设置
JVM堆的设置是指java程序运行过程中JVM可以调配使用的内存空间的设置.JVM在启动的时候会自动设置Heap size的值，
其初始空间(即-Xms)是物理内存的1/64，最大空间(-Xmx)是物理内存的1/4。可以利用JVM提供的-Xmn -Xms -Xmx等选项可
进行设置。Heap size 的大小是Young Generation 和Tenured Generaion 之和。
提示：在JVM中如果98％的时间是用于GC且可用的Heap size 不足2％的时候将抛出此异常信息。
提示：Heap Size 最大不要超过可用物理内存的80％，一般的要将-Xms和-Xmx选项设置为相同，而-Xmn为1/4的-Xmx值。
解决方法：手动设置Heap size，修改启动参数
JAVA_OPTS=”-server -Xms800m -Xmx800m   -XX:MaxNewSize=256m”
三、实例，以下给出1G内存环境下java jvm 的参数设置参考：
JAVA_OPTS=”-server -Xms800m -Xmx800m -XX:PermSize=64M -XX:MaxNewSize=256m -XX:MaxPermSize=128m -Djava.awt.headless=true ”
Windows
set JAVA_OPTS=%JAVA_OPTS% -Xms128m -Xmx256m -XX:PermSize=128m -XX:MaxPermSize=256m -XX:MaxNewSize=256m -Dfile.encoding=GBK
echo “JAVA_OPTS=”$JAVA_OPTS
Linux
JAVA_OPTS=”$JAVA_OPTS -Xms128m -Xmx256m -XX:PermSize=128m -XX:MaxPermSize=256m -XX:MaxNewSize=256m -Dfile.encoding=GBK”
echo “JAVA_OPTS=”$JAVA_OPTS

JVM内存JAVA_OPTS参数说明

我经常会这样来设置服务器端的JVM:JAVA_OPTS=”-server -Xms2048m -Xmx2048m -Xss512k”

-server:一定要作为第一个参数，在多个CPU时性能佳刘兵召写于2008-12-25 12:40
-Xms：初始Heap大小，使用的最小内存,cpu性能高时此值应设的大一些
-Xmx：java heap最大值，使用的最大内存刘兵召写于2008-12-25 12:40
上面两个值是分配JVM的最小和最大内存，取决于硬件物理内存的大小，建议均设为物理内存的一半。刘兵召写于2008-12-25 12:40
-XX:PermSize:设定内存的永久保存区域刘兵召写于2008-12-25 12:40
-XX:MaxPermSize:设定最大内存的永久保存区域刘兵召写于2008-12-25 12:40
-XX:MaxNewSize:刘兵召写于2008-12-25 12:40
-Xss 15120 这使得JBoss每增加一个线程（thread)就会立即消耗15M内存，而最佳值应该是128K,默认值好像是512k.刘兵召写于2008-12-25 12:40
+XX:AggressiveHeap 会使得 Xms没有意义。这个参数让jvm忽略Xmx参数,疯狂地吃完一个G物理内存,再吃尽一个G的swap。刘兵召写于2008-12-25 12:40
-Xss：每个线程的Stack大小刘兵召写于2008-12-25 12:40
-verbose:gc 现实垃圾收集信息刘兵召写于2008-12-25 12:40
-Xloggc:gc.log 指定垃圾收集日志文件刘兵召写于2008-12-25 12:40
-Xmn：young generation的heap大小，一般设置为Xmx的3、4分之一刘兵召写于2008-12-25 12:40
-XX:+UseParNewGC ：缩短minor收集的时间刘兵召写于2008-12-25 12:40
-XX:+UseConcMarkSweepGC ：缩短major收集的时间刘兵召写于2008-12-25 12:40
提示：此选项在Heap Size 比较大而且Major收集时间较长的情况下使用更合适。