JVM系列：三、JVM 优化与问题排查思路

在 上一篇 中，我们已经掌握了当下几种主流的垃圾收集器了。本篇将介绍 JVM 的优化和常见问题。

JVM 怎么优化？

可以从如下两个方向去优化：

1. GC 的选择

   根据不同的业务场景，去选择对应 GC。

2. 参数优化

   对于参数优化，有两个方向，应用基础参数配置 和 观察 gc.log 或 JVM 内存监控。

启动参数优化

   我们有必要在一个应用启动前，结合实际的业务场景，为它设置一些 JVM 参数，来达到更合理的分配计算机资源、记录信息排查突发问题等目的。

初始化参数用例:

场景：projectA 是一个用于检查第三方和第一方账单的定时任务，基于 SpringBoot 构建，小内存（分配资源：2G，1 core），以吞吐量为主，故采用 UseParallelGC。

LOG_DIR=/date/projectA
$Java_opts=" -Dfile.encoding-utf-8 -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:${LOG_DIR}/gc.log -XX:+HeapDumpOnOutOfMemoryError -XX:PrintTenuringDistribution -XX:HeapDumpPath=${LOG_DIR}/autoDump.hprof -XX:ErrorFile=${LOG_DIR}/java_error_%p.log "
$java_mem_opts=" -Xmn800m -Xms1600m -Xmx1600m -XX:MetaspaceSize=128m"
$java_jmx_opts=" -Dcom.sun.management.jmxremote.port=5000 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false "

nohup -server  $Java_opts $java_mem_opts clazz.Main 1>/dev/null 2>&1 &

观察 JVM 内存变化

   参考案例

---

应用问题排查

   在排查 JVM 问题时，可以采用 总-分 的方式进行排查，先通过查看 Linux 的整体情况，再盘点 JVM 的整体情况，再结合最近的业务盘点业务、GC日志，逐步解决问题。

Linux 监控命令

常用的监控命令

应用检测命令

jps (java process status)

查看当前用户下，正在运行的 Java 程序信息

jps [ options ]  pid 
jps -m  显示主函数输入的参数
jps -l  显示应用程序 主类完整 / 全限定包类名 或 jar完整名称
jps -v  列出程序启动时的 jvm 参数
jps -V   输出通过.hotsportrc 或 -XX:Flags=<filename> 指定的 jvm 参数

jinfo

查看运行中 JVM 的参数，也可以修改部分运行参数（ java -XX:+PrintFlagsFinal 中，标识为 manageable 的参数是可修改的，如CMSWaitDuration）。

jinfo [option] <pid>   (to connect to running process)

where <option> is one of:
-flag <name>         to print the value of the named VM flag
-flag [+|-]<name>    to enable or disable the named VM flag
-flag <name>=<value> to set the named VM flag to the given value
-flags               to print VM flags
-sysprops            to print Java system properties
<no option>          to print both of the above

jmap

打印进程、核心文件或远程调试服务器的 共享对象内存映射或堆内存详细信息。官文

jmap [ option ] pid

option 选项：

-dump:[live,] format=b, file=filename ： Dumps the Java heap in hprof binary format to filename. The `live` suboption is optional, but when specified, only the active objects in the heap are dumped.(即dump前执行一次 FullGC)

-F : Force. Use this option with the jmap -dump or jmap -histo option when the pid does not respond. The live suboption is not supported in this mode.

-finalizerinfo 打印正等候回收的对象的信息.

-heap 打印 heap 的概要信息，GC使用的算法，heap的配置等

-histo[:live] 打印每个class的实例数目,内存占用,类全名信息. VM的内部类名字开头会加上前缀”*”. 如果live子参数加上后,只统计活的对象数量. 

-permstat 打印classload和jvm heap长久层的信息. 包含每个classloader的名字,活泼性,地址,父classloader和加载的class数量. 另外,内部String的数量和占用内存数也会打印出来. 
	
-h | -help 打印辅助信息 

-J 传递参数给jmap启动的jvm. 

jmap -heap < PID > ：heap 的概要信息；
部分参数解释：

Heap Configuration:         # Heap堆配置信息
   MinHeapFreeRatio         = 0 # JVM堆最小空闲比率(default 40)
   MaxHeapFreeRatio         = 100  # JVM堆最大空闲比率(default 70)
   MaxHeapSize              = 536870912 (512.0MB) # 堆最大值，可以通过 -XX:MaxHeapSize 或 -Xmx设置
   NewSize                  = 44564480 (42.5MB) # 新生代大小
   MaxNewSize               = 178782208 (170.5MB) # 新生代的最大大小
   OldSize                  = 89653248 (85.5MB) # 老年代大小
   NewRatio                 = 2 # 新生代与老生代的大小比率 1:2
   SurvivorRatio            = 8 # 年轻代中Eden区与两个Survivor区的比值。注意Survivor区有两个。如：8，表示Eden：Survivor=8：2
   MetaspaceSize            = 21807104 (20.796875MB) # jdk1.7有永久代，jdk1.8更换成了Metaspace
   CompressedClassSpaceSize = 1073741824 (1024.0MB)  # class信息存放的空间大小
   MaxMetaspaceSize         = 17592186044415 MB # Metaspace是使用的直接内存，理论上可以无限大（内存+硬盘缓冲区）
   G1HeapRegionSize         = 0 (0.0MB) # 设置的 G1 区域的大小。值是 2 的幂，范围是 1 MB 到 32 MB 之间。目标是根据最小的 Java 堆大小划分出约 1024/2048 个区域。

jmap -dump:format=b,file=heap.hprof < PID > ：将 PID 进程的堆快照按二进制的方式存储到 heap.hprof 中去。得到的文件可以使用 MAT 去分析。

jstat : JVM数据统计工具

官文

jstat [ generalOption | outputOptions vmid [ interval[s|ms] [ count ] ]

vmid、interval、count分别是进程号，打印间隔时间（s或ms），打印次数，其中 option 有如下常用的几个（得到的结果列表介绍可在官方文档中查找）：

-class 统计class loader行为信息 ，如总共加载了多少个类
-gc 统计jdk gc时heap信息
-gccapacity 统计不同的generations相应的heap容量情况
-gccause 统计gc的情况，（同-gcutil）和引起gc的事件
-gcnew 统计gc时，新生代的情况
-gcnewcapacity 统计gc时，新生代heap容量
-gcold 统计gc时，老年区的情况
-gcoldcapacity 统计gc时，老年区heap容量
-gcpermcapacity 统计gc时，permanent区heap容量
-gcutil 统计gc时，heap情况

常用的组合命令：jstat -gcutil 2s (每隔2s打印pid的gc和内存占用情况) / jstat -gccause 2s（每隔2s打印pid的GC Cause）

jcmd

jcmd <pid> GC.heap_dump -all=true,进行一次不做 Full GC 的 heap dump

Java应用监测命令行工具

---

JVM 内存、CPU 高占用问题排查方向

首先应该去查看是否有错误日志记录。当从错误日志里找不到可用信息时，排查时的几个方向如下：

一、JVM 堆内存启动参数与代码目前运行场景是否相符

二、 dump出内存使用情况，分析各个类占用情况，定位是否有业务代码的问题

  在对线上高内存占用应用指向 dump 命令后（dump中，没有加入live参数），得到的文件大小和应用实际内存使用大小相差巨大，为什么会出现这种情况？？？？？

三、查看内存回收情况，判断内存是否可以被回收

  如果内存可以被回收掉，那么是在某个操作下一些比较大的对象被创建了出来，重点从日志中定位排查这些对象；如果内存一直是一个高占用状态，那么可能是内存泄漏，重点排查 dump 文件中，导致内存泄漏的大对象。

Mat工具使用

拿到dump文件后，利用MAT解析，生成报告，记得把MAT的启动参数里面的最大内存调到足够大，如果有条件可以调到dump文件大小的2/3应该够用了。

JVM heap dump使用Mat分析

用例

应用场景介绍：
  应用基于 SpringBoot + JDK 1.8 构建，提供一个 http 接口，用于向静态成员变量中添加对象，静态成员变量中的对象不会被 GC 掉，所以当该接口请求到一定次数后，会出现内存溢出。应用启动参数如下：

-Xms500M -Xmx500M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=D:\Software\MemoryAnalyzer-1.10.0.20200225-win32.win32.x86_64\autoHeapDump.hprof

 	public  static Map<Object,Object> OOM_MAP=new ConcurrentHashMap<>();
    static int startId=0;
	@RequestMapping("/addobj")
    @ResponseBody
    public String addobj(){
        int objNum=10000+startId;
        for (; startId < objNum; startId++) {
            Users users = new Users();
            users.setMessageId(startId);
            users.setUsername("name "+startId);
            OOM_MAP.put(startId,users);
        }
        return "oom_map success addd object "+ objNum;
    }

结论:

  先放从下面列举的图片中，得到的结论。通过 mat 分析各个对象的占用的 Retained Heap ，当 Retained Heap 值已经接近 堆中老年代 分配的内存时，这个对象就应当重点排查。 Bigest Objects 查看与之有关联的类数量和类 Retained Heap 值，也可以参考 Leak Suspects 的分析。

应用启动时状态

接口被多次请求后

老年代占满后的内存使用变化

结合下图和请求多次的第一张图，可知，当 Old 被占满后，会使用 eden 区域，eden 区域被占满后，GC 会释放掉一部分内存，腾出新的空间

---

JVM 常见问题记录

全表查询导致的 Full GC 频繁，MySQL 短时间不可用：

场景：

  项目 A 在内网，提供给公司内部其他项目使用的 http 接口，A 已经运行很长一段时间了。某天，项目 B 上线，B是有前端交互功能的应用，在 B 的使用过程中，前端页面抛出了 SQL 执行异常。遂排查错误，发现是由于 B 在调用 A 的接口时，A 内存占用高，A 和 B 的数据库是同一台，所以 B 的页面上抛出了 SQL 执行失败的异常。

老年代内存占用高，Full GC 频繁：

项目内存分配信息：

统计gc时，heap情况如下：

  出现这种老年代占用过高时，可以先把堆内存设置大一些，一是可以让线上环境暂时跑起来，二是可以观察一下内存是否可以被回收掉，获取到更多的信息。

  堆内存放大4倍后，发现虽然老年代内存会迅速膨胀，但在执行一次 full gc 后，内存恢复到正常水平，所以定位这种问题，是在某一个接口被请求后，查出了大量的数据，放到了内存中，方法执行结束执行 full gc 后，内存恢复到正常水平，查找日志定位方法，处理 sql 问题，遂解决问题。

总结：

   遇到该类型的问题，首先看一下应用日志和 JVM 日志，再使用各种工具观察内存变化情况，逐步定位问题代码，缩小排查范围。

Metaspace 空间动态调整，频繁触发 FullGC

现象：
   线上 JVM MetaspaceSize 采用默认配置，应用启动初期频繁 FullGC，启动一段时间后 GC 频率稳定。

GC 日志：
   MetaspaceSize 使用默认值，应用启动初期动态调整 Metaspace 大小，1min 内触发了 3 次 FullGC

MetaspaceSize 使用默认值 官方文档：
Specify a higher value for the option MetaspaceSize to avoid early garbage collections induced for class metadata. The amount of class metadata allocated for an application is application-dependent and general guidelines do not exist for the selection of MetaspaceSize. The default size of MetaspaceSize is platform-dependent and ranges from 12 MB to about 20 MB.

Java HotSpot(TM) 64-Bit Server VM (25.201-b09) for linux-amd64 JRE (1.8.0_201-b09), built on Dec 15 2018 11:35:59 by "java_re" with gcc 7.3.0
Memory: 4k page, physical 2097152k(2091028k free), swap 0k(0k free)
CommandLine flags: -XX:ErrorFile=/data/log_check-bill/java_error_%p.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/log_check-bill/java_error.hprof -XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=2147483648 -XX:NewRatio=1 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops
2020-12-03T16:49:25.847+0800: 8.067: [Full GC (Metadata GC Threshold) 2020-12-03T16:49:25.847+0800: 8.067: [Tenured: 0K->20930K(1048576K), 0.3393432 secs] 620829K->20930K(1992320K), [Metaspace: 20669K->20669K(1067008K)], 0.3395654 secs] [Times: user=0.32 sys=0.01, real=0.34 secs]
2020-12-03T16:49:35.577+0800: 17.797: [Full GC (Metadata GC Threshold) 2020-12-03T16:49:35.577+0800: 17.797: [Tenured: 20930K->52441K(1048576K), 0.5912357 secs] 676079K->52441K(1992320K), [Metaspace: 34349K->34349K(1081344K)], 0.5914109 secs] [Times: user=0.53 sys=0.02, real=0.59 secs]
2020-12-03T16:49:52.081+0800: 34.301: [GC (Allocation Failure) 2020-12-03T16:49:52.081+0800: 34.301: [DefNew: 838912K->47128K(943744K), 0.6701127 secs] 891353K->99570K(1992320K), 0.6703567 secs] [Times: user=0.60 sys=0.05, real=0.67 secs]
2020-12-03T16:49:53.084+0800: 35.304: [Full GC (Metadata GC Threshold) 2020-12-03T16:49:53.084+0800: 35.304: [Tenured: 52441K->69472K(1048576K), 0.2917267 secs] 121220K->69472K(1992320K), [Metaspace: 57079K->57079K(1101824K)], 0.2919305 secs] [Times: user=0.25 sys=0.01, real=0.29 secs]

观察日志，发现两个点：

• 每次 FullGC 后，Metaspace 的使用空间几乎没有下降
• 最后一次 FullGC 后，Metaspace 稳定在 60M 左右。

   所以，为了避免 Metaspace 的动态调整，结合 MinMetaspaceFreeRatio（最小空闲率）， 调整 MeatspaceSize = 60M / (1- 40%) = 100 M ，设置 -XX:MeatspaceSize=128M，避免启动初期的频繁扩容。

   当然如果条件允许的话，建议将 -XX:MeatspaceSize 和 -XX:MaxMeatspaceSiz 设置相等，避免空间的动态调整。

配置参数，启动初期发生3次正常的 YoungGC。

Java HotSpot(TM) 64-Bit Server VM (25.201-b09) for linux-amd64 JRE (1.8.0_201-b09), built on Dec 15 2018 11:35:59 by "java_re" with gcc 7.3.0
Memory: 4k page, physical 2097152k(2089108k free), swap 0k(0k free)
CommandLine flags: -XX:ErrorFile=/data/log_check-bill/java_error_%p.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/log_check-bill/java_error.hprof -XX:InitialHeapSize=1677721600 -XX:MaxHeapSize=1677721600 -XX:MetaspaceSize=134217728 -XX:NewRatio=1 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops
2020-12-11T14:26:58.091+0800: 4.065: [GC (Allocation Failure) 2020-12-11T14:26:58.091+0800: 4.065: [DefNew: 655360K->24604K(737280K), 0.1368309 secs] 655360K->24604K(1556480K), 0.1369216 secs] [Times: user=0.08 sys=0.01, real=0.14 secs]
2020-12-11T14:27:03.982+0800: 9.956: [GC (Allocation Failure) 2020-12-11T14:27:03.983+0800: 9.956: [DefNew: 679964K->42806K(737280K), 0.2631822 secs] 679964K->42806K(1556480K), 0.2632663 secs] [Times: user=0.19 sys=0.04, real=0.26 secs]
2020-12-11T14:27:09.066+0800: 15.040: [GC (Allocation Failure) 2020-12-11T14:27:09.066+0800: 15.040: [DefNew: 698166K->47040K(737280K), 0.1713024 secs] 698166K->54034K(1556480K), 0.1713975 secs] [Times: user=0.15 sys=0.00, real=0.18 secs]

总结：

   对于 Metaspace 、Heap 空间大小的动态调整，都必定会触发一次 FullGC，所以，为了减少不必要的 FullGC 带来的应用停顿，尽量将成对出现的空间大小配置参数设置成固定的，如 -Xms 和 -Xmx，-XX:MaxNewSize 和 -XX:NewSize，-XX:MetaSpaceSize 和 -XX:MaxMetaSpaceSize 等

美团cms gc参考文档