jvm日志分析

比如我们用以下JVM参数来运行代码：

-XX:NewSize=5242880 -XX:MaxNewSize=5242880 
-XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 
-XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=10485760
-XX:+UseParNewGC -XX:+UseConcMarkSweepGC

上述参数都是基于JDK 1.8版本来设置的，不同的JDK版本对应的参数名称是不太一样的，但是基本意思是类似的。

上面“-XX:InitialHeapSize”和“-XX:MaxHeapSize”就是初始堆大小和最大堆大小，“-XX:NewSize”和“-XX:MaxNewSize”是初始新生代大小和最大新生代大小，“-XX:PretenureSizeThreshold=10485760”指定了大对象阈值是10MB。

接着我们需要在系统的JVM参数中加入GC日志的打印选型，如下所示：

    -XX:+PrintGCDetils：打印详细的gc日志

    -XX:+PrintGCTimeStamps：这个参数可以打印出来每次GC发生的时间

    -Xloggc:gc.log：这个参数可以设置将gc日志写入一个磁盘文件

加上这个参数之后，jvm参数如下所示：

-XX:NewSize=5242880 -XX:MaxNewSize=5242880 
-XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 
-XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=10485760 
-XX:+UseParNewGC -XX:+UseConcMarkSweepGC
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log

日志分析
0.268: [GC (Allocation Failure) 0.269: [ParNew: 4030K->512K(4608K), 0.0015734 secs] 4030K->574K(9728K), 0.0017518 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

0.268：
这个意思就是你的系统运行以后过了多少秒发生了本次GC
ParNew: 4030K->512K(4608K), 0.0015734 secs
4030K->512K(4608K) ：
年轻代可用空间是4608KB，也就是4.5MB，为啥是4.5MB呢？Eden区是4MB，两个Survivor中只有一个是可以放存活对象的，另外一个是必须一致保持空闲的，所以他考虑年轻代的可用空间，就是Eden+1个Survivor的大小，也就是4.5MB。
4030K->512K：
意思就是对年轻代执行了一次GC，GC之前都使用了4030KB了，但是GC之后只有512KB的对象是存活下来的。
0.0015734 secs：
这个就是本次gc耗费的时间，看这里来说大概耗费了1.5ms，仅仅是回收3MB的对象而已。
4030K->574K(9728K), 0.0017518 secs：
这段话指的是整个Java堆内存的情况
意思是整个Java堆内存是总可用空间9728KB（9.5MB），其实就是年轻代4.5MB+老年代5M，然后GC前整个Java堆内存里使用了4030KB，GC之后Java堆内存使用了574KB。

par new generation   total 4608K, used 2601K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)

 eden space 4096K,  51% used [0x00000000ff600000, 0x00000000ff80a558, 0x00000000ffa00000)

 from space 512K, 100% used [0x00000000ffa80000, 0x00000000ffb00000, 0x00000000ffb00000)

 to   space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)

par new generation total 4608K, used 2601K，这就是说“ParNew”垃圾回收器负责的年轻代总共有4608KB（4.5MB）可用内存，目前是使用了2601KB（2.5MB）。

0.716: [GC (Allocation Failure) 0.717: [ParNew: 139776K->2677K(157248K), 0.0038770 secs] 139776K->2677K(506816K), 0.0041376 secs] [Times: user=0.03 sys=0.01, real=0.00 secs]
在默认的内存分配策略下，年轻代一共可用空间是150MB左右，这里还包含了一点Survivor区域的大小

0.771: [Full GC (Metadata GC Threshold) 0.771: [CMS: 0K->2161K(349568K), 0.0721349 secs] 20290K->2161K(506816K), [Metaspace: 9201K->9201K(1058816K)], 0.0722612 secs] [Times: user=0.12 sys=0.03, real=0.08 secs]
接着我们来看这次GC，这就是Full GC了，而且通过“Metadata GC Threshold”清晰看到，是Metaspace区域满了，所以触发了Full GC
这个时候看下面的日志，20290K->2161K(506816K)，这个就是说堆内存（年轻代+老年代）一共是500MB左右，然后有20MB左右的内存被使用了，这个必然是年轻代用的。

工具检测

1 使用命令

jstat

内存情况
jstat -gc 45894 1000 10
ps -ef | grep ‘java’

jmap

内存情况
jmap -heap 45894
会在当前目录下生成一个dump.hprof文件(存放堆内存的对象快照)
jmap -dump:live,format=b,fie=dump.hprof PID

jhat

启动jhat服务
jhat dump.hprof -prot 7000
访问端口就可以在游览器上访问然后分析dump.hprof文件
2使用监测工具
Zabbix. OpenFalcon.Ganglia

优化参数配置

1 优化老年代的内存碎片问题

在降低了Full GC频率之后，务必设置如下参数“-XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=0”，每次Full GC后都整理一下内存碎片。
否则如果每次Full GC过后，都造成老年代里很多内存碎片，那么必然导致下一次Full GC更快到来，因为内存碎片会导致老年代可用内存变少。

2 jvm模板

8G的机器给JVM堆内存分配4G，其他进程会使用内存，别让JVM堆内存把机器内存给占满
-Xms4096M -Xmx4096M -Xmn3072M -Xss1M -XX:PermSize=256M -XX:MaxPermSize=256M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=92
-XX:SurvivorRatio=6 -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=0

一个参数是“-XX:+CMSParallelInitialMarkEnabled”，这个参数会在CMS垃圾回收器的“初始标记”阶段开启多线程并发执行。
大家应该还记得初始标记阶段，是会进行Stop the World的，会导致系统停顿，所以这个阶段开启多线程并发之后，可以尽可能优化这个阶段的性能，减少Stop the World的时间。

另外一个参数是“-XX:+CMSScavengeBeforeRemark”，这个参数会在CMS的重新标记阶段之前，先尽量执行一次Young GC。
其实大家都记得，CMS的重新标记也是会Stop the World的，所以所以如果在重新标记之前，先执行一次Young GC，就会回收掉一些年轻代里没有人引用的对象。
所以如果先提前回收掉一些对象，那么在CMS的重新标记阶段就可以少扫描一些对象，此时就可以提升CMS的重新标记阶段的性能，减少他的耗时。

3 如何排查类不停的被加载到元空间 059案例

接着我们就有点奇怪了，到底是什么类不停的被加载到JVM的Metaspace区域里去？
这个时候就需要在JVM启动参数中加入如下两个参数了：
“-XX:TraceClassLoading -XX:TraceClassUnloading”
这两个参数，顾名思义，就是追踪类加载和类卸载的情况，他会通过日志打印出来JVM中加载了哪些类，卸载了哪些类。
加入这两个参数之后，我们就可以看到在Tomcat的catalina.out日志文件中，输出了一堆日志，里面显示类似如下的内容：

总结：
1 出现full gc的原因多是慢处理和高并发
2 cpu过高
(1)一般是创建过多线程并发执行，且工作负载都很重，
(2) 频繁full gc
3 full gc 的四种可能
(1）内存分配不合理，导致对象频繁进入老年代，进而引发频繁的Full GC；
(2) 存在内存泄漏等问题，就是内存里驻留了大量的对象塞满了老年代，导致稍微有一些对象进入老年代就会引发Full GC；
(3) 永久代里的类太多，触发了Full GC
(4)以上三种都不存在，可能有错误的执行“System.gc()”导致

导出dump文件
jmap -dump:live,format=b,file=/home/server/heap.bin 55025
使用mat分析
https://www.eclipse.org/mat/downloads.php

-XX:+CMSParallelInitialMarkEnabled表示在初始标记的多线程执行，减少STW；
-XX:+CMSScavengeBeforeRemark：在重新标记之前执行minorGC减少重新标记时间；
-XX:+CMSParallelRemarkEnabled:在重新标记的时候多线程执行，降低STW；
-XX：CMSInitiatingOccupancyFraction=92和-XX:+UseCMSInitiatingOccupancyOnly配套使用，如果不设置后者，jvm第一次会采用92%但是后续jvm会根据运行时采集的数据来进行GC周期，如果设置后者则jvm每次都会在92%的时候进行gc；
-XX:+PrintHeapAtGC:在每次GC前都要GC堆的概况输出

内存溢出有3种

堆内存溢出

原因：高并发，慢查询

永久代（元空间）内存溢出

原因：使用字节码技术生产了太多的类

java虚拟机栈 内存溢出

通常来说，我们会设置每个线程的栈内存就是1MB，假设你一个JVM进程内包括他自带的后台线程，你依赖的第三方组件的后台线程，加上你的核心工作线程（比如说你部署在Tomcat中，那就是Tomcat的工作线程），还有你自己可能额外创建的一些线程，可能你一共JVM中有1000个线程
那么1000个线程就需要1GB的栈内存空间，每个线程有1MB的空间。
所以基本上这套内存模型是比较合理的，其实一般来说，4核8G机器上运行的JVM进程，比如一个Tomcat吧，他内部所有的线程数量加起来在几百个是比较合理的，也就占据几百MB的内存，线程太多了，4核CPU负载也会过高，也并不好。
另外大家需要设置这个程序的JVM参数如下：-XX:ThreadStackSize=1m，通过这个参数设置JVM的栈内存为1MB。
原因：递归调用方法

所以Metaspace区域+堆内存+几百个线程的栈内存，就是JVM一共对机器上的内存资源的一个消耗

OOM处理排查

在OOM的时候自动dump内存快照

我们可以让JVM在OOM时dump一份内存快照，事后我们只要分析这个内存快照，一下就可以知道是哪些可恶的对象占用了所有的内存，并且还无法释放。

-XX:+HeapDumpOnOutOfMemoryError 在OOM的时候自动dump内存快照出来
-XX:HeapDumpPath=/usr/local/app/oom 把内存快照放到哪儿去

jvm模板

“-Xms4096M -Xmx4096M -Xmn3072M -Xss1M -XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFaction=92 -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=0 -XX:+CMSParallelInitialMarkEnabled -XX:+CMSScavengeBeforeRemark -XX:+DisableExplicitGC -XX:+PrintGCDetails -Xloggc:gc.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/usr/local/app/oom”

内存耗费过高

内存耗费超过50%感到有点惊讶，因为这说明他几乎快要把分配给他的内存消耗殆尽了！
1 在内存使用这么高的情况下会发生什么？

第一种:是内存使用率居高不下，导致频繁的进行full gc，gc带来的stop the world问题影响了服务。
第二种:是内存使用率过多，导致JVM自己发生OOM。
第三种:是内存使用率过高，也许有的时候会导致这个进程因为申请内存不足，直接被操作系统把这个进程给杀掉了！

首先我们先使用jstat分析了一下JVM运行的情况，确实内存使用率很高，也确实经常发生gc，但是实际上gc耗时每次也就几百毫秒，并没有耗费过多的时间，也就是说虽然gc频率高，但是其实是个常规现象。

sar -n DEV 1 2 网卡流量