JVM 问题排查SOP

1. JVM问题

1. young gc 频繁（5s一次）

2. young gc 时间偏高（大于40ms）

3. young gc 时间陡增（平常20ms左右，某一次陡增到200ms）

4. full gc 频繁（1小时一次）

5. full gc STW时间长(大于100ms)

6. 内存泄露

7. 内存溢出

2. 先练内功

2.1 java执行过程

 

 

2.2 java堆分代结构

     

2.3 java线程结构

1. java递归有什么问题

2. java值传递是形参还是实参

 

2.4 java进程内存结构

a. 如何查看java进程内存大小

b. top VIRT,RES 区别

c. JIT编译器，java为什么不全部翻译成本机机器代码

d. java 线程占用空间(-Xss) java -XX:+PrintFlagsFinal -version | grep ThreadStackSize

f. 推荐一个小程序JVMPocket

 

3. young gc 频繁

现象：cat上查看jvm.younggc.count指标1分钟高于12次

分析：

1. young gc 触发条件是eden区满，没有其他条件

2. 调大eden区，不能缩小survivor区和old区大小（避免顾此失彼）

3. eden区扩大后，观察young gc耗时是否增加（这属于一个平衡）

 

4. young gc 时间偏高

现象：cat上查看jvm.younggc.meantime avg时间高于40ms

分析：

1. young gc 耗时主要在如下几个方面：a. 扫描eden区域和一个survivor区存活的对象，b.拷贝存活的对象到另外一个survivor区，c.晋升到达年龄阈值的对象到老年代

2. 扫描eden区耗时，没有地方体现。根据经验上限2G的新生代，扫描eden区耗时不是问题。

3. 如果每次存活的对象过多，拷贝时间就会比较长：a. eden区存活对象过多，判断是否young gc太频繁，如果不频繁，可能有内存泄露。 b. survivor区存活的对象多，需要观察对象年龄分布。 打印年龄分布： -XX:+PrintTenuringDistribution，调小 survivor区的目标使用率-XX:TargetSurvivorRatio（默认值50%） ，或者晋升年龄 -XX:MaxTenuringThreshold（默认值15）

4. 如果survivor存活对象控制住，晋升到老年代的对象也就可以控制住

 

5. young gc 时间陡增

现象：cat上查看jvm.younggc.meantime max时间平常20ms左右，某一次突然陡增到200ms

分析：

1. 根据上一点分析，young gc时间主要消耗在如上三个方面。如果是陡增，扫描时间肯定不变，只能够是存活的对象突然变多了。

2. 观察存活对象是否比正常情况比有明显增加，如果是，需要观察流量是否陡增。如果不是，进入下一步

3. 查看机器磁盘是否繁忙，磁盘繁忙也会导致young gc时间变长，表现为real time 远远大于 user time+ sys time。 原因2个：

a. gc日志需要写磁盘，如果磁盘发生阻塞，这部分等待时间也算在young gc内。解决方案：young gc日志写入/dev/shm/目录（实际为内存）

b. jvm jstat命令所需要的信息，在发生young gc的时候也需要写入磁盘。解决方案：禁用jstat所需要的信息写入磁盘，增加jvm参数-XX:+PerfDisableSharedMem。负面影响：jstat命令无法使用，只能够通过cat监控jvm情况

4. 查看机器cpu是否繁忙，cpu繁忙会导致young gc 时间变长，表现为 sys time 陡增。这个自我无解决方案，需要找到占用cpu高的服务去解决占用cpu高的原因。

 

6. full gc 频繁

现象：cat上查看jvm.fullgc.count 大于1小时一次

分析：

首先需要定位full gc 发生原因，后续才能够出对应的解决方案，具体参考：https://blog.csdn.net/liwenshui322/article/details/88866564

 

7. full gc stw耗时长

现象：这里只讨论background cms算法，如果退化到了serial 收集器或者属于forceground cms，参考第6点的解决方案。 cms有2个阶段是STW的，如果某一个时间超过100ms，是需要优化的

分析：

1. cms收集器主要步骤为如下七步： a. CMS Initial Mark， b. CMS-concurrent-mark，c. CMS-concurrent-preclean，d. CMS-concurrent-abortable-preclean， e. CMS Final Remark，f. CMS-concurrent-sweep，g. CMS-concurrent-reset。其中a和e是STW的

2. 需要具体了解cms每一步都干了什么，参考https://www.cnblogs.com/zhangxiaoguang/p/5792468.html

2018-07-11T21:04:29.988+0800: 1921223.677: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2237310K(2796224K)] 2246340K(4054528K), 0.0046492 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2018-07-11T21:04:29.993+0800: 1921223.682: Total time for which application threads were stopped: 0.0065988 seconds, Stopping threads took: 0.0000531 seconds
2018-07-11T21:04:29.993+0800: 1921223.682: [CMS-concurrent-mark-start]
2018-07-11T21:04:30.121+0800: 1921223.810: Total time for which application threads were stopped: 0.0023569 seconds, Stopping threads took: 0.0001396 seconds
2018-07-11T21:04:30.146+0800: 1921223.835: Total time for which application threads were stopped: 0.0026732 seconds, Stopping threads took: 0.0001360 seconds
2018-07-11T21:04:30.167+0800: 1921223.856: [CMS-concurrent-mark: 0.169/0.174 secs] [Times: user=0.29 sys=0.00, real=0.17 secs]
2018-07-11T21:04:30.168+0800: 1921223.856: [CMS-concurrent-preclean-start]
2018-07-11T21:04:30.183+0800: 1921223.871: [CMS-concurrent-preclean: 0.015/0.015 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]
2018-07-11T21:04:30.183+0800: 1921223.872: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2018-07-11T21:04:35.203+0800: 1921228.892: [CMS-concurrent-abortable-preclean: 4.808/5.020 secs] [Times: user=6.23 sys=0.36, real=5.02 secs]
2018-07-11T21:04:35.206+0800: 1921228.894: [GC (CMS Final Remark) [YG occupancy: 402407 K (1258304 K)]1921228.894: [Rescan (parallel) , 0.0636181 secs]1921228.958: [weak refs processing, 0.0802412 secs]1921229.038: [class unloading, 0.0465207 secs]1921229.085: [scrub symbol table, 0.0130538 secs]1921229.098: [scrub string table, 0.0018163 secs][1 CMS-remark: 2237310K(2796224K)] 2639718K(4054528K), 0.2130768 secs] [Times: user=0.36 sys=0.00, real=0.21 secs]
2018-07-11T21:04:35.419+0800: 1921229.108: Total time for which application threads were stopped: 0.2155978 seconds, Stopping threads took: 0.0001271 seconds
2018-07-11T21:04:35.419+0800: 1921229.108: [CMS-concurrent-sweep-start]
2018-07-11T21:04:36.422+0800: 1921230.111: Total time for which application threads were stopped: 0.0029692 seconds, Stopping threads took: 0.0001217 seconds
2018-07-11T21:04:37.119+0800: 1921230.808: [CMS-concurrent-sweep: 1.697/1.700 secs] [Times: user=2.39 sys=0.07, real=1.70 secs]
2018-07-11T21:04:37.120+0800: 1921230.809: [CMS-concurrent-reset-start]
2018-07-11T21:04:37.126+0800: 1921230.815: [CMS-concurrent-reset: 0.006/0.006 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

3. 一般都是 CMS Final Remark这一步耗时比较长，原因也比较常见，扫描新生代耗时长。因为需要扫描新生代所有对象，验证是否有新生代新增对象引用了老年代的对象。可以通过加一个参数（-XX:+CMSScavengeBeforeRemark）强制发生一次young gc，来回收新生代对象。或者控制如下三个参数

此阶段涉及几个参数：
-XX:CMSMaxAbortablePrecleanTime（默认5s）：当abortable-preclean阶段执行达到这个时间时才会结束
-XX:CMSScheduleRemarkEdenSizeThreshold（默认2m）：控制abortable-preclean阶段什么时候开始执行， 即当eden使用达到此值时，才会开始abortable-preclean阶段
-XX:CMSScheduleRemarkEdenPenetratio（默认50%）：控制abortable-preclean阶段什么时候结束执行
​
人话是：这个阶段当eden区占用>=2m的时候开始执行，当eden去使用率到达50%停止（如果开始的时候就超过了50%，就会一次young gc之后才有可能达到50%）。另外，如果执行时间超过5s也会停止。
场景1： 开始的时候eden区占用低于50%，这个时候如果remark时间长，说明eden区50%空间过大，调小参数 CMSScheduleRemarkEdenPenetratio 参数
场景2： 开始的时候eden区占用高于50%，这个时候如果remark时间长，说明没有等到一次young gc，需要调大CMSMaxAbortablePrecleanTime 参数

8. 内存泄露

分类：堆内内存泄露，堆外内存泄露

1. 堆内内存泄露

主要指老年代垃圾回收的时候，有些内存始终回收不掉（这部分内存对程序无益）。表现形式为，jvm 老年代占比一直维持比较高（比如50%）。

解决方案：

jmap -histo:live pid

或者

jmap -dump:format=b,file=d:/heap.hprof <pid>

用jprofiler分析dump下来的内存

一个示例：

2. 堆外内存泄露

java除了分配-Xmx堆内存外，还可以直接操控堆外内存的分配，这部分内存在触发system.gc的时候会被回收。但是有时候，可能full gc 也不能够回收这部分内存，就发生了泄露。表现形式为top命令查看res列，计算出堆外内存大约是多少，并且经历full gc是否有下降。

解决方案：

解决方案有点麻烦，简而言之：需要在内存分配malloc的时候封装一层，监控内存分配发起方都是谁，然后查找这个发起方代码对应的位置。

参考文章：http://www.longtask.net/2018/11/15/swap-used-full/

 

8. 内存溢出

a. java.lang.OutOfMemoryError:Java heap space

java堆内存不够用，一般是-Xmx设置过小，或者发生了内存泄露，导致内存被占用。

b. java.lang.OutOfMemoryError: Metaspace

元空间溢出，原因：系统的代码非常多或引用的第三方包非常多或者通过动态代码生成类加载等方法，导致元空间的内存占用很大

解决方案：

调大 -XX:MaxMetaspaceSize

c. java.lang.OutOfMemoryError: Direct buffer memory

直接内存溢出，-XX:MaxDirectMemorySize，并及时clear内存

d. StackOverflowError

线程请求的栈深度大于虚拟机所允许的最大深度, 或者没到最大长度，但是线程内存耗尽。注意递归是否过深

e.java.lang.OutOfMemoryError:Unable to create new native thread

当JVM向OS请求创建一个新线程时，而OS却无法创建新的native线程 ulimit -u 查看允许创建的最大线程数。

 

内存溢出参考

https://www.jianshu.com/p/2fdee831ed03
https://segmentfault.com/a/1190000017226359