JVM的调试与优化

JVM的调试与优化

Java8 默认使用并行GC，即ParallelGC，老年代和新生代使用的都是，为了保证吞吐量优先

吞吐量=运行用户代码时间/(运行用户代码时间+运行垃圾收集时间)

堆内存是大概是物理内存的1/4

堆内存的大小对系统的影响

堆太小很容易寄，因为堆内存溢出，会发生很多次full GC，然后溢出报错

堆内存如果配的特别小，而程序中内存使用的量又特别大，就会导致内存很快的没有内存用了，导致堆内存溢出堆内存特别小的时候，GC频率特别高，影响性能

CMS

初始标记，整个JVM暂停的阶段，非常短，

为什么非常短

因为他只标记了根对象下的第一个对象，也就是说把所有对象排成很多个纵队，只标记第一个，所有很短

G1不分代

如何解决死锁

1. 把所有的锁定状态都加上超时时间，超过了时间，对象还锁着，就将线程终止掉
2. 使用fastthread.io这个网站可以对堆栈信息复制过去，可以查看

内存分析和相关工具

分配速率到底影响什么

分配速率小了，系统跑不快，分配速率大了，系统没有崩，说明GC的频率很高，那说明我们的GC占用我们的系统资源很多，分配速率意味着影响youngGC,影响着new对象

new出来的对象放在Eden区，如果增大Eden区会怎样，蓄水池效应，最终的效果是，影响Minor GC的次数和时间，进而影响吞吐量，在某些情况下，只要增加年轻代的大小，即可降低分配速率过高所造成的影响，增加年轻代空间并不会降低分配速率，但是会减少GC的频率。如果每次GC后都只有少量对象存活，minor GC的暂停时间就不会明显增加

举例

GC排查实战案例

情况:

我们做的项目有一个高并发请求的服务，系统使用SpringBoot框架，指标采集使用Micrometer(Micrometer 为基于 JVM 的应用程序的性能监测数据收集提供了一个通用的 API，支持多种度量指标类型，这些指标可以用于观察、警报以及对应用程序当前状态做出响应。),监控数据上报给Datadog(云应用程序监控平台)

问题现象的描述

最近一段时间，通过监控指标发现，有一个服务节点的最大GC暂停时间经常会达到400ms以上，当时客户那边要求这种情况必须解决，因为服务调用的超时时间为1s,要求最大GC的暂停时间不超过200ms,平均暂停时间达到100ms以内，对客户的交易策略产生了极大的影响。

解决思路

先去查看CPU的使用情况，系统负载(系统负载（System Load）是系统CPU繁忙程度的度量，即有多少进程在等待被CPU调度（进程等待队列的长度）。)大概有到5，CPU使用率不到10%，没看出来什么很大问题

然后去查看GC使用情况，在那个服务的节点前老年代使用大幅下降，发生了一次full GC，事后去复盘分析，发现发生最大暂停时间时，老年代的使用空间再缓慢上升，因此并不是fullGC造成的，但当时没察觉到，就怀疑是fullGC导致的长时间GC暂停，观察到老年代对应的内存池是ps_old_gen,查找资料知道ps代表ParallelGC垃圾收集器，也是Java8默认的垃圾收集器，查看JVM的启动参数，启动参数只是指定了堆内存的大小和运行内存的大小，当时怀疑是GC处理器上，因为并行GC是吞吐量优先的，为了最大的系统处理能力而牺牲了单次的暂停时间，导致暂停时间会比较长。

后来我们就更换了GC

‐Xmx4g ‐Xms4g ‐XX:+UseG1GC ‐XX:MaxGCPauseMillis=50

当时还犯了一个小错误，当时是设置GC最大停顿时间MaxGCPauseMill时在数值后还加上了单位，后来改正后启动成功

然后等待健康检测自动切换为新的服务节点，继续查看指标，看了看暂停时间，每个GC的暂停时间都降下来了，基本在50ms以内，比较符合预期，当时就想着事情结束了，后来过了一段时间，我们发现了一个superise,DataDog监控到GC暂停时间达到了1300ms,当时我们的部门整个都是懵的，以为是指标错了，这个应该是10s内的暂停时间全部加到一起的

然后我们注册了GC事件监听使用JMX,把相关信息打印出来，通过这种方式，我们可以在程序中监听GC事件，并将相关信息汇总或输出到日志，在启动一次，运行一段时间后，日志情况显示，不是fullGC而是年轻代GC,而且暂停时间达到了1800多ms,当时我们都认为这个没有道理，我也认为这种情况不合理，而且观察CPU使用量也不高，当时又翻了很多资料，想去证明这个1800ms不是暂停时间，而是GC事件的结束时间减去开始时间，以上方法都没奏效，我们想不到其他的解决办法，就开始打印GC日志

‐Xmx4g ‐Xms4g ‐XX:+UseG1GC ‐XX:MaxGCPauseMillis=50‐Xloggc:gc.log ‐XX:+PrintGCDetails ‐XX:+PrintGCDateStamps

重新启动，继续排查，运行一段时间后又发现了超长的暂停时间，

开始分析GC日志，因为不涉及敏感数据，我们把GC日志下载到本地进行分析，定位到这次暂停时间超长的GC时间，查看关键信息，前后的GC事件当时都是正常的，也没发现FullGC或者并发标记周期，但还是发现了几个可疑的点

physical 144145548k(58207948k free) JVM启动时，物理内存 137GB, 空闲内存55GB.

[Parallel Time: 1861.0 ms, GC Workers: 48] 垃圾收集器工作线程 48

个。

user=1.67 用户线程耗时 1.67秒；

sys=14.00 系统调用和系统等待时间 14秒；

real=1.87 secs 实际暂停时间 1.87 秒；

GC之前，年轻代使用量2GB，堆内存使用量3.6GB, 存活区2MB，可推断出老年代使用量 1.6GB;

GC之后，年轻代使用量为0，堆内存使用量2GB，存活区254MB， 那么老年代大约1.8GB，那么 内存提升量为200MB左右 。

这样分析之后，可以得出结论：

年轻代转移暂停，复制了400MB左右的对象，却消耗了1.8秒，系统调用和系统等待的时间达到了14秒。

JVM看到的物理内存137GB。。。

推算出JVM看到的CPU内核数量 72个，因为 GC工作线程 72* 5/8 ~= 48个。

看到这么多的GC工作线程我就开始警惕了，毕竟堆内存才指定4GB。

按照一般的CPU和内存资源配比，常见的比例差不多是 4核4GB ， 4核8GB 这样的。

看看对应的CPU负载监控信息：

通过和运维同学的沟通，得到这个节点的配置被限制为 4核8GB

这样一来，GC暂停时间过长的原因就定位到了:

K8S的资源隔离和JVM未协调好，导致JVM看见了72个CPU内核，默认的并行GC线程设置为:72* 5/8 + 3 = 48个 ，但是K8S限制了这个Pod只能使用4个CPU内核的计算量，致使GC发生时，48个线程在4个CPU核心上发生资源竞争，导致大量的上下文切换。

处置措施为：

限制GC的并行线程数量

事实证明，打印GC日志确实是一个很有用的排查分析方法。

并行GC线程数设置成了四个

‐Xmx4g ‐Xms4g ‐XX:+UseG1GC ‐XX:MaxGCPauseMillis=50 ‐XX:ParallelGCThreads=4
‐Xloggc:gc.log ‐XX:+PrintGCDetails ‐XX:+PrintGCDateStamps

设置STW阶段的并行 worker 线程数量。

如果逻辑处理器小于等于8个，则默认值 n 等于逻辑处理器的数量。

如果逻辑处理器大于8个，则默认值 n 等于处理器数量的 n/8+3 。 在大多数情况下都是个比较合理的值。 如果是高配置的 SPARC 系统，则默认值 n 大约等于逻辑处理器数量的 5/16 。

‐XX:ConcGCThreads=n

设置并发标记的GC线程数量。 默认值大约是 ParallelGCThreads 的四分之一。一般来说不用指定并发标记的GC线程数量，只用指定并行的即可。

重新启动之后，看看GC暂停时间指标：

后续的监控发现，这个参数确实解决了问题。