18-3.JVM调优案例分析案例分析

这是我参与11月更文挑战的第20天,活动详情查看:2021最后一次更文挑战

案例分析

1. JVM运行情况预估

现在有一个线上的异常情况。具体的详情如下;

  • 机器配置:2核4G
  • JVM内存大小:2G
  • 系统运行时间:7天
  • 期间发生的Full GC次数和耗时:500多次,200多秒
  • 期间发生的Young GC的次数和耗时:1万多次,500多秒。

如何能够知道系统运行期间发生了多少次young gc和多少次full gc,并且他们的耗时是多少呢?使用如下命令:

jstat -gcutil 进程ID
复制代码

然后就可以看到程序运行的结果了;

这几个参数的具体含义是什么呢?

  • S0:Survivor 1区当前使用比例
  • S1:Survivor 2区当前使用比例
  • E:Eden区使用比例
  • O:老年代使用比例
  • M:元数据区使用比例
  • CCS:指针压缩使用比例
  • YGC:年轻代垃圾回收次数
  • YGCT:年轻代垃圾回收消耗时间
  • FGC:老年代垃圾回收次数
  • FGCT:老年代垃圾回收消耗时间
  • GCT:垃圾回收消耗总时间

2. JVM优化的思路

JVM优化的目标其实主要是Full GC。只要不发生Full GC,基本就不会出现OOM。所以如何优化Full GC就是我们的目标。往前推,老年代的对象是怎么来的呢?从新生代来的,那么我们就要避免朝生夕死的新生代对象进入到老年代。

1) 分析GC数据:

期间发生的Full GC次数和耗时:500多次,200多秒。那么平均7 * 24 * 3600秒/500 = 20分钟发生一次Full GC, 每次full GC耗时:200秒/500=400毫秒;

期间发生的Young GC次数和耗时:1万多次,500多秒,那么平均7 * 24 * 3600秒/10000 = 60秒也就是1分钟发生一次young GC,每次young GC耗时:500/10000=50毫秒;

其实,从full GC和young GC的时间来看,还好,不太长。主要是发生的频次,full gc发生的频次太高了,20分钟一次,通常我们的full gc怎么也要好几个小时触发一次,甚至1天才触发一次。而young gc触发频次也过于频繁,1分钟触发一次。

2)梳理内存模型

根据上述信息,我们可以画一个内存模型出来。

先来看看原系统的JVM参数配置信息

‐Xms1536M ‐Xmx1536M ‐Xmn512M ‐Xss256K ‐XX:SurvivorRatio=6 ‐XX:MetaspaceSize=256M ‐XX:MaxMetaspaceSize=256M 2 ‐XX:+UseParNewGC ‐XX:+UseConcMarkSweepGC ‐XX:CMSInitiatingOccupancyFraction=75 ‐XX:+UseCMSInitiatingOccupancyOnly
复制代码
  • 堆空间:1.5G
  • 新生代:512M
  • 线程大小:256k
  • ‐XX:SurvivorRatio新生代中Eden区域和Survivor区域:6。也就是Eden:S0: S1 = 6:1:1
  • 元数据空间:256M
  • 采用的垃圾收集器:CMS
  • -XX:CMSInitiatingOccupancyFraction=75:CMS在对内存占用率达到75%的时候开始GC
  • -XX:+UseCMSInitiatingOccupancyOnly: 只是用设定的回收阈值(上面指定的70%), 如果不指定, JVM仅在第一次使用设定值, 后续则自动调整.

根据参数我们梳理如下内存模型。堆内存空间都分配好了,那么上面说了每过60s触发一次Young GC,那么就是说,平均每秒会产生384/60=6.4M的垃圾。而老年代,每过20分钟就会触发一次GC,而老年代可用的内存空是0.75G,也就是750多M。

现在的问题,为什么每过20分钟,就会有750M的对象挪到老年代呢?解决了这个问题,我们就可以阻止对象挪到老年代

结合对象挪动到老年的规则分析这个模型可能会有哪些问题:

  1. 大对象
  2. 顽固的对象
  3. 动态年龄判断机制
  4. 老年代空间担保机制
  • 首先分析:我们的系统里会不会有大对象。其实代码使我们自己写的,我们知道里面没有特别大的对象。在年轻代放不下了,直接进入老年代,所以这种情况排除
  • 第二个顽固的对象:我们这里通常都是朝生夕死的对象,顽固的对象就是系统的那些对象,如果是系统对象,也不应该是每过20分钟都会产生700M老顽固对象啊。
  • 第三个动态年龄判断机制:一批对象的总大小大于这块Survivor区域内存大小的50%(-XX:TargetSurvivorRatio可以指定),那么此时大于等于这批对象年龄最大值的对象,就可以直接进入老年代了。这个是有可能的,可能在垃圾收集的时候,Survivor区放不下了,那么就会直接放入到老年代。

既然这种情况有可能,那我们就来分析一下:

线程每秒中产生6M多的垃圾,如果并发量比较大的时候, 处理速度比较慢,可能1s处理不完,假设处理完数据要四五秒,就按5s来算,那一秒就可能产生30M的垃圾,这时候触发Dden区垃圾回收的时候,这30M的垃圾要进入到S1区,而S1区很可能本身就有一部分对象了,再加上这30M就大于S1区的一半了,直接进入老年代。

这只是一种可能。

  • 第四个触发老年代空间担保机制:其实触发老年代空间担保机制的概率很小,通常都是老年代空间很小的会后,会触发。我们这里老年代比较大,所以基本不可能。

综上所述,现在最有可能频繁触发GC的可能的原因是动态年龄判断机制。我们之前在做优化的时候,遇到过。可以将Survivor区域放大一点,就可以了。

3. 案例模拟分析

我们用下面这个案例来模拟分析上述情况。分析找到问题。

第一步:启动主程序

  • 这时一个springboot的web程序,内容很简单。创建项目的时候注意选择web就可以了
  • 然后里面定义了一个User对象。这个User对象比较特别,里面有个参数a分配0.1M的内存空间。
package com.jvm;
​
public class User {
  
  private int id;
  private String name;
​
  byte[] a = new byte[1024*100];
......
​
}
​
复制代码
  • 接下来定义了一个接口- 类
package com.jvm;
​
import org.springframework.util.StopWatch;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;
​
import java.util.ArrayList;
​
@RestController
public class IndexController {
​
    @RequestMapping("/user/process")
    public String processUserData() throws InterruptedException {
        ArrayList<User> users = queryUsers();
​
        for (User user: users) {
            //TODO 业务处理
            System.out.println("user:" + user.toString());
        }
        return "end";
    }
​
    /**
     * 模拟批量查询用户场景
     * @return
     */
    private ArrayList<User> queryUsers() {
        ArrayList<User> users = new ArrayList<>();
        for (int i = 0; i < 5000; i++) {
            users.add(new User(i,"zhuge"));
        }
        return users;
    }
}
复制代码

接口类很简单,每次调用接口,先创建5000个用户,然后让这5000个用户区执行各自的业务逻辑。需要注意的是5000个用户占用内存空间约500M。也就是说,每次调用这个接口,都会产生500M的对象。

  • 然后定义一个测试类,测试类
​
@RunWith(SpringRunner.class)
@SpringBootTest(classes={Application.class})// 指定启动类
public class ApplicationTests {
​
  @Bean
  public RestTemplate restTemplate() {
    return new RestTemplate();
  }
​
  @Autowired
  private RestTemplate restTemplate;
​
  @Test
  public void test() throws Exception {
    for (int i = 0; i < 10000; i++) {
      String result = restTemplate.getForObject("http://localhost:8080/user/process", String.class);
      Thread.sleep(1000);
    }
  }
​
}
​
复制代码

测试类很简单,就是手动调用上面的接口。循环调用10000次。如果启动10000次的话,

  • 启动主程序
@SpringBootApplication
public class Application {
​
  public static void main(String[] args) {
    SpringApplication.run(Application.class, args);
  }
​
  @Bean
  public RestTemplate restTemplate() {
    return new RestTemplate();
  }
}
复制代码

第二步:配置jvm参数

我们要模拟线上的情况,所以参数也设置和线上一样的情况。

-Xms1536M -Xmx1536M -Xmn512M -Xss256K -XX:SurvivorRatio=6 -XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly
复制代码

第三步:使用jstat gc命令观察垃圾收集情况

程序启动起来以后,可以使用jps命令查看进程,输入命令查看gc触发情况

jstat -gc 进程ID   [间隔时间  触发次数]
  
jstat -gc 8620 1000  10000
表示观察8620这个进程,每隔1s打印一次gc情况,连续打印10000次
复制代码

我们看到,程序启动以后都是出发了4次young gc, 1次full gc。程序启动触发gc都是ok的。后面基本没有什么垃圾产生了。

第四步:启动test代码,调用process接口

这一步没啥说的,直接启动程序就可以了

第五步:观察终端gc的变化

为了保险期间,我们查看一下运行的参数是不是我们配置的参数

jinfo -flags 8620
复制代码

程序启动以后,我们发现频发的触发了gc,新生代gc触发很频繁,老年代也很频繁。老年代gc触发那么频繁,那就是有问题了。根据上面的分析,最有可能的情况是动态年龄分配机制。可能产生的对象在survivor区放不下,直接进入老年代 。处理这个问题的方法是,扩大年轻代空间。

第六步:优化1:增加新生代内存空间,以及老年代触发gc的比例

  • 新生代空间扩大到1G
  • 老年代空间缩小为0.5G
  • 还要重新设置一个参数就是CMSInitiatingOccupancyFraction,原来是是75,这个参数是为了防止触发老年代空间担保机制。但这样会有25%的空间基本是空闲的。当很少触发full gc的时候,这个值可以缩小一些。
-Xms1536M -Xmx1536M -Xmn1024M -Xss256K -XX:SurvivorRatio=6 -XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=92 -XX:+UseCMSInitiatingOccupancyOnly
复制代码

内存空间变化后:

再次启动项目,看运行结果:

image

基本没有gc触发。说明我们的优化是有效的。然后在启动测试程序:

这一次我们发现,触发gc的次数相对来说少了,gc的速度相对于上一次小了一些,但是又有新的问题发生:老年代gc比年轻代还有频繁。这是怎么回事呢?有什么情况会让老年代触发gc的频率大于年轻代呢?

这可能会有几种情况

  • 元数据空间不够,导致full gc,不断扩大元数据空间

元数据空间比较好看,我们直接看输出的参数

红框圈出的就是元数据空间和元数据已用空间。我们来看实际使用情况

通过观察,我们发现元数据大小基本上是不变的。所以,元数据空间不太会增加导致触发full gc。

  • 显式的调用System.gc(),造成多余的full gc触发。

这个情况一般在线上都会进制成都代码触发full gc。量通过­XX:+DisableExplicitGC参数禁用,如果加上了这个JVM启动参数,那么代码中调用System.gc()没有任何效果。

  • 触发了老年代空间担保机制

结合之前学习的理论,我们知道,老年代空间担保机制。有可能在触发一次minor GC的时候触发两次Full GC。

来复习一下:

  • 年轻代每次minor gc之前JVM都会计算下老年代剩余可用空间。如果这个可用空间小于年轻代里现有的所有对象大小之和(包括垃圾对象),就会看一个“-XX:-HandlePromotionFailure”(jdk1.8默认就设置了)的参数是否设置了,如果有这个参数,就会看看老年代的可用内存大小,是否大于之前每一次minor gc后进入老年代的对象的平均大小

  • 如果上一步结果是小于或者之前说的参数没有设置,那么就会直接触发一次Full GC,然后再触发Minor GC, 如果回收完还是没有足够空间存放新的对象就会发生"OOM"

  • 如果minor gc之后剩余存活的需要挪动到老年代的对象大小还是大于老年代可用空间,那么也会触发full GC,Full GC完之后如果还是没有空间放minor gc之后的存活对象,则也会发生“OOM”。

在梳理一下这块逻辑,为什么叫担保机制。在触发Minor GC的时候,进行了一个条件判断,预估老年代空间是否能够放的下新生代的对象,如果能够放得下,那么就直接触发Minor GC, 如果放不下,那么先触发Full GC。在触发Full GC的时候设置了担保参数会增加异步判断,而不是直接触发Full GC。判断老年代剩余可用空间 是否小于 历史每次Minor GC后进入老年代对象的平均值。这样的判断可以减少Full GC的次数。因为新生代在触发Full GC以后是会回收一部分内存的,剩余部分再放入老年代,可能就能放下了。

通过回顾,我们看到老年代空间担保机制中,当触发一次Minor GC的时候,有可能会触发两次Full GC。这样就导致Full GC的次数大于Minor GC。

由此可见,我们这次优化是失败的, 还引入了新的问题。这里还有可能是大对象导致的,不一定是非常大的一个对象,也可能是多个对象在一个时刻产生的大对象。

第七步:优化2:查找大对象

我们在查找是否有大对象,或者某一个时间是否有大对象占用较大的内存空间,可以使用命令或者终端查看

jmap -histo 进程ID
复制代码

前面都是系统对象,往下找我们看到一个自定义对象User,这个实例有10000个,占用内存空间240M

或者使用jvisualvm

点击内存,就可以实时查看到系统进程的内存占用情况。点击内存其实就是对 【jmap -histo 进程ID】命令的包装

内存占用最多的是byte[]数组,占用了内存的95%。是什么情况让byte数组占用这么多的内存呢?这个通常都是用户自定义对象造成的。往下看,我们看到了User对象,user对象占用了12w字节数据,有5000个实例。

假如这个代码不是我们写的,是别人写的,我们不熟悉。这时候可以通过以下方法定位问题

  • new User()对象不多。可以通过反查定位找出问题。

       /**
         * 模拟批量查询用户场景
         * @return
         */
        private ArrayList<User> queryUsers() {
            ArrayList<User> users = new ArrayList<>();
            for (int i = 0; i < 5000; i++) {
                users.add(new User(i,"zhuge"));
            }
            return users;
        }
    复制代码

    我们发现,在这里竟然创建了5000个对象。不过5000个对象应该也不多。通常一个对象也就几k,我们进到User里看看

    public class User {
      
      private int id;
      private String name;
    ​
      byte[] a = new byte[1024*100];
    }
    复制代码

    意外发现,User里定义了一个byte数组,一个byte数组占用100k的空间。那问题就是这里了。

  • 如果系统中new User()对象很多,应该怎么办呢?

    系统中有这么多对象,说明什么问题呢?new User()在反复执行,这样的话,cpu占用率应该不低。如果这边不好找,我们可以看看cpu占用情况。

这里的cpu其实就是对命令是对jstack命令的封装【jstack 4013440|grep -A 10 67187778】

通过分析我们看出第一个take()方法占用cpu最高,达到98%,但是这个是什么东西,我们不太熟悉,看看第二个,第二个是queryUsers(),这个是我们自己的方法,可以看看这个方法的具体内容:

 /**
     * 模拟批量查询用户场景
     * @return
     */
    private ArrayList<User> queryUsers() {
        ArrayList<User> users = new ArrayList<>();
        for (int i = 0; i < 5000; i++) {
            users.add(new User(i,"zhuge"));
        }
        return users;
    }
​
public class User {
  
  private int id;
  private String name;
​
  byte[] a = new byte[1024*100];
}
复制代码

刚好就定位到这段代码,我们发现他一下查询了5000个对象,并且每个对象里定义了一个大对象。这样我们就定位到了问题。

所以在查询数据的时候,要注意是否有大对象,如果有大对象的话,需要预估一下内存消耗。剩下就是代码优化的问题了。

我们这里降低查询用户数从一次5000到一次500,然后重启代码试一下:

private ArrayList<User> queryUsers() {
        ArrayList<User> users = new ArrayList<>();
        for (int i = 0; i < 500; i++) {
            users.add(new User(i,"zhuge"));
        }
        return users;
    }
复制代码

来看看运行效果

触发young gc的频率降低了,而且基本不会触发full gc了。说明这次优化是有效的。