既然学习JVM,阅读GC日志是处理Java虚拟机内存问题的基础技能,它只是一些人为确定的规则,没有太多技术含量。
既然如此,那么在IDE的控制台打印GC日志是必不可少的了。现在就告诉你怎么打印。
(1)如果你用的是Eclipse,打印GC日志的操作如下:
在上图的箭头处加上-XX:+PrintGCDetails这句话。于是,运行程序后,GC日志就可以打印出来了:
(2)如果你用的是IntelliJ IDEA,打印GC日志的操作如下:
在上图的箭头处加上-XX:+PrintGCDetails这句话。于是,运行程序后,GC日志就可以打印出来了:
当然了,光有-XX:+PrintGCDetails这一句参数肯定是不够的,下面我们详细介绍一下更多的参数配置。
-verbose:gc -XX:+printGC
解释:可以打印GC的简要信息。比如:
[GC 4790K->374K(15872K), 0.0001606 secs]
[GC 4790K->374K(15872K), 0.0001474 secs]
[GC 4790K->374K(15872K), 0.0001563 secs]
[GC 4790K->374K(15872K), 0.0001682 secs]
上方日志的意思是说,GC之前,用了4M左右的内存,GC之后,用了374K内存,一共回收了将近4M。内存大小一共是16M左右。
-XX:+PrintGCDetails
解释:打印GC详细信息。
-XX:+PrintGCTimeStamps
解释:打印CG发生的时间戳。
理解GC日志的含义:
例如下面这段日志:
[GC[DefNew: 4416K->0K(4928K), 0.0001897 secs] 4790K->374K(15872K), 0.0002232 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
上方日志的意思是说:这是一个新生代的GC。方括号内部的“4416K->0K(4928K)”含义是:“GC前该内存区域已使用容量->GC后该内存区域已使用容量(该内存区域总容量)”。而在方括号之外的“4790K->374K(15872K)”表示“GC前Java堆已使用容量->GC后Java堆已使用容量(Java堆总容量)”。
再往后看,“0.0001897 secs”表示该内存区域GC所占用的时间,单位是秒。
再比如下面这段GC日志:
上图中,我们先看一下用红框标注的“[0x27e80000, 0x28d80000, 0x28d80000)”的含义,它表示新生代在内存当中的位置:第一个参数是申请到的起始位置,第二个参数是申请到的终点位置,第三个参数表示最多能申请到的位置。上图中的例子表示新生代申请到了15M的控件,而这个15M是等于:(eden space的12288K)+(from space的1536K)+(to space的1536K)。
-Xloggc:log/gc.log
解释:指定GC log的位置,以文件输出。帮助开发人员分析问题。
-XX:+PrintHeapAtGC
解释:每一次GC前和GC后,都打印堆信息。
例如:
上图中,红框部分正好是一次GC,红框部分的前面是GC之前的日志,红框部分的后面是GC之后的日志。
-XX:+TraceClassLoading
解释:监控类的加载。
例如:
[Loaded java.lang.Object from shared objects file]
[Loaded java.io.Serializable from shared objects file]
[Loaded java.lang.Comparable from shared objects file]
[Loaded java.lang.CharSequence from shared objects file]
[Loaded java.lang.String from shared objects file]
[Loaded java.lang.reflect.GenericDeclaration from shared objects file]
[Loaded java.lang.reflect.Type from shared objects file]
-XX:+PrintClassHistogram
解释:按下Ctrl+Break后,打印类的信息。
例如:
举例、当参数设置为如下时:
-Xmx20m -Xms5m
然后我们在程序中运行如下代码:
System.out.println("Xmx=" + Runtime.getRuntime().maxMemory() / 1024.0 / 1024 + "M"); //系统的最大空间 System.out.println("free mem=" + Runtime.getRuntime().freeMemory() / 1024.0 / 1024 + "M"); //系统的空闲空间 System.out.println("total mem=" + Runtime.getRuntime().totalMemory() / 1024.0 / 1024 + "M"); //当前可用的总空间
运行效果:
保持参数不变,在程序中运行如下代码:(分配1M空间给数组)
byte[] b = new byte[1 * 1024 * 1024]; System.out.println("分配了1M空间给数组"); System.out.println("Xmx=" + Runtime.getRuntime().maxMemory() / 1024.0 / 1024 + "M"); //系统的最大空间 System.out.println("free mem=" + Runtime.getRuntime().freeMemory() / 1024.0 / 1024 + "M"); //系统的空闲空间 System.out.println("total mem=" + Runtime.getRuntime().totalMemory() / 1024.0 / 1024 + "M");
运行效果:
注:Java会尽可能将total mem的值维持在最小堆。
保持参数不变,在程序中运行如下代码:(分配10M空间给数组)
byte[] b = new byte[10 * 1024 * 1024]; System.out.println("分配了10M空间给数组"); System.out.println("Xmx=" + Runtime.getRuntime().maxMemory() / 1024.0 / 1024 + "M"); //系统的最大空间 System.out.println("free mem=" + Runtime.getRuntime().freeMemory() / 1024.0 / 1024 + "M"); //系统的空闲空间 System.out.println("total mem=" + Runtime.getRuntime().totalMemory() / 1024.0 / 1024 + "M"); //当前可用的总空间
运行效果:
如上图红框所示:此时,total mem 为7M时已经不能满足需求了,于是total mem涨成了16.5M。
保持参数不变,在程序中运行如下代码:(进行一次GC的回收)
System.gc(); System.out.println("Xmx=" + Runtime.getRuntime().maxMemory() / 1024.0 / 1024 + "M"); //系统的最大空间 System.out.println("free mem=" + Runtime.getRuntime().freeMemory() / 1024.0 / 1024 + "M"); //系统的空闲空间 System.out.println("total mem=" + Runtime.getRuntime().totalMemory() / 1024.0 / 1024 + "M"); //当前可用的总空间
运行效果:
问题1: -Xmx(最大堆空间)和 –Xms(最小堆空间)应该保持一个什么关系,可以让系统的性能尽可能的好呢?
问题2:如果你要做一个Java的桌面产品,需要绑定JRE,但是JRE又很大,你如何做一下JRE的瘦身呢?
设置新生代大小
新生代(eden+2*s)和老年代(不包含永久区)的比值
例如:4,表示新生代:老年代=1:4,即新生代占整个堆的1/5
设置两个Survivor区和eden的比值
例如:8,表示两个Survivor:eden=2:8,即一个Survivor占年轻代的1/10
现在运行如下这段代码:
- public class JavaTest {
- public static void main(String[] args) {
- byte[] b = null;
- for (int i = 0; i < 10; i++)
- b = new byte[1 * 1024 * 1024];
- }
- }
我们通过设置不同的jvm参数,来看一下GC日志的区别。
(1)当参数设置为如下时:(设置新生代为1M,很小)
-Xmx20m -Xms20m -Xmn1m -XX:+PrintGCDetails
运行效果:
总结:
没有触发GC
由于新生代的内存比较小,所以全部分配在老年代。
(2)当参数设置为如下时:(设置新生代为15M,足够大)
-Xmx20m -Xms20m -Xmn15m -XX:+PrintGCDetails
运行效果:
上图显示:
没有触发GC
全部分配在eden(蓝框所示)
老年代没有使用(红框所示)
(3)当参数设置为如下时:(设置新生代为7M,不大不小)
-Xmx20m -Xms20m –Xmn7m -XX:+PrintGCDetails
运行效果:
总结:
进行了2次新生代GC
s0 s1 太小,需要老年代担保
(4)当参数设置为如下时:(设置新生代为7M,不大不小;同时,增加幸存代大小)
-Xmx20m -Xms20m -Xmn7m -XX:SurvivorRatio=2 -XX:+PrintGCDetails
运行效果:
总结:
进行了至少3次新生代GC
s0 s1 增大
(5)当参数设置为如下时:
-Xmx20m -Xms20m -XX:NewRatio=1 -XX:SurvivorRatio=2 -XX:+PrintGCDetails
运行效果:
(6)当参数设置为如下时: 和上面的(5)相比,适当减小幸存代大小,这样的话,能够减少GC的次数
-Xmx20m -Xms20m -XX:NewRatio=1 -XX:SurvivorRatio=3 -XX:+PrintGCDetails
OOM时导出堆到文件
根据这个文件,我们可以看到系统dump时发生了什么。
导出OOM的路径
例如我们设置如下的参数:
-Xmx20m -Xms5m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=d:/a.dump
上方意思是说,现在给堆内存最多分配20M的空间。如果发生了OOM异常,那就把dump信息导出到d:/a.dump文件中。
然后,我们执行如下代码:
- Vector v = new Vector();
- for (int i = 0; i < 25; i++)
- v.add(new byte[1 * 1024 * 1024]);
上方代码中,需要利用25M的空间,很显然会发生OOM异常。现在我们运行程序,控制台打印如下:
现在我们去D盘看一下dump文件:
上图显示,一般来说,这个文件的大小和最大堆的大小保持一致。
我们可以用VisualVM打开这个dump文件。
注:关于VisualVM的使用,可以参考下面这篇博客:
使用 VisualVM 进行性能分析及调优:IBM Developer
或者使用Java自带的Java VisualVM工具也行:
上图中就是dump出来的文件,文件中可以看到,一共有19个byte已经被分配了。
在OOM时,执行一个脚本。
可以在OOM时,发送邮件,甚至是重启程序。
例如我们设置如下的参数:
-XX:OnOutOfMemoryError=D:/tools/jdk1.7_40/bin/printstack.bat %p //p代表的是当前进程的pid
上方参数的意思是说,执行printstack.bat脚本,而这个脚本做的事情是:D:/tools/jdk1.7_40/bin/jstack -F %1 > D:/a.txt,即当程序OOM时,在D:/a.txt中将会生成线程的dump。
设置永久区的初始空间和最大空间。也就是说,jvm启动时,永久区一开始就占用了PermSize大小的空间,如果空间还不够,可以继续扩展,但是不能超过MaxPermSize,否则会OOM。
他们表示,一个系统可以容纳多少个类型
代码举例:
我们知道,使用CGLIB等库的时候,可能会产生大量的类,这些类,有可能撑爆永久区导致OOM。于是,我们运行下面这段代码:
- for(int i=0;i<100000;i++){
- CglibBean bean = new CglibBean("geym.jvm.ch3.perm.bean"+i,new HashMap());
- }
上面这段代码会在永久区不断地产生新的类。于是,运行效果如下:
总结:
如果堆空间没有用完也抛出了OOM,有可能是永久区导致的。
堆空间实际占用非常少,但是永久区溢出 一样抛出OOM。
设置栈空间的大小。通常只有几百K
决定了函数调用的深度
每个线程都有独立的栈空间
局部变量、参数 分配在栈上
注:栈空间是每个线程私有的区域。栈里面的主要内容是栈帧,而栈帧存放的是局部变量表,局部变量表的内容是:局部变量、参数。
我们来看下面这段代码:(没有出口的递归调用)
- public class TestStackDeep {
- private static int count = 0;
-
- public static void recursion(long a, long b, long c) {
- long e = 1, f = 2, g = 3, h = 4, i = 5, k = 6, q = 7, x = 8, y = 9, z = 10;
- count++;
- recursion(a, b, c);
- }
-
- public static void main(String args[]) {
- try {
- recursion(0L, 0L, 0L);
- } catch (Throwable e) {
- System.out.println("deep of calling = " + count);
- e.printStackTrace();
- }
- }
- }
上方这段代码是没有出口的递归调用,肯定会出现OOM的。
如果设置栈大小为128k:
-Xss128K
运行效果如下:(方法被调用了294次)
如果设置栈大小为256k:(方法被调用748次)
意味着函数调用的次数太深,像这种递归调用就是个典型的例子。