JVM性能调优(四):使用 jstat 摸清线上系统的JVM运行状况

x33g5p2x  于11个月前 转载在 Java  
字(5.1k)|赞(0)|评价(0)|浏览(87)

写在前面

        本文用一个工具来分析运行中的系统,他的对象增长的速率,Young GC的触发频率,Young GC的耗时,每次Young GC后有多少对象是存活下来的,每次Young GC过后有多少对象进入了老年代,老年代对象增长的速率,Full GC的触发频率, Full GC的耗时。

1、jstat

        检查JVM的整体运行情况,比较实用的工具之一,就是jstat。

        看到当前运行中的系统,他的JVM内的Eden、Survivor、老年代的内存使用情况,还有Young GC和Full gC的执行次数以及耗时。 通过这些指标,我们可以轻松的分析出当前系统的运行情况,判断当前系统的内存使用压力以及GC压力,还有就是内存分配是否合理。

2、jstat -gc PID

        在生产机器linux上,jps命令显示Java进程的PID。接着就针对我们的Java进程执行:jstat -gc PID。这就可以看到这个Java进程(其实本质就是一个JVM)的内存和GC情况了。
运行这个命令之后会看到如下列,给大家解释一下:

S0C:这是From Survivor区的大小
S1C:这是To Survivor区的大小
S0U:这是From Survivor区当前使用的内存大小
S1U:这是To Survivor区当前使用的内存大小
EC:这是Eden区的大小
EU:这是Eden区当前使用的内存大小
OC:这是老年代的大小
OU:这是老年代当前使用的内存大小
MC:这是方法区(永久代、元数据区)的大小MU:这是方法区(永久代、元数据区)的当前使用的内存大小
YGC:这是系统运行迄今为止的Young GC次数
YGCT:这是Young GC的耗时
FGC:这是系统运行迄今为止的Full GC次数
FGCT:这是Full GC的耗时
GCT:这是所有GC的总耗时

3、其他jstat命令

        还有一些命令可以看到更多详细的信息,如下所示:

jstat -gccapacity PID:堆内存分析
jstat -gcnew PID:年轻代GC分析,这里的TT和MTT可以看到对象在年轻代存活的年龄和存活的最大年龄
jstat -gcnewcapacity PID:年轻代内存分析
jstat -gcold PID:老年代GC分析
jstat -gcoldcapacity PID:老年代内存分析
jstat -gcmetacapacity PID:元数据区内存分析

4**、到底该如何使用jstat工具?**

先明确一下,我们分析线上的JVM进程,最想要知道的信息有哪些?

        包括如下:新生代对象增长的速率,Young GC的触发频率,Young GC的耗时,每次Young GC后有多少对象是存活下来的,每次Young GC过后有多少对象进入了老年代,老年代对象增长的速率,Full GC的触发频率,Full GC的耗时

        只要知道了这些信息,其实我们就可以结合之前几周的文章分析过的JVMGC优化的方法,合理分配内存空间,尽可能让对象留在年轻代不进入老年代,避免发生频繁的Full GC。这就是对JVM最好的性能优化了!

4.1、新生代对象增长的速率

我们平时对jvm第一个要了解的就是随着系统运行,每秒钟会在年轻代的Eden区分配多少对象
方法:

只要在线上linux机器上运行如下命令:jstat -gc PID 1000 10
这行命令意思就是每隔1秒钟更新出来最新的一行jstat统计信息,一共执行10次jstat统计

通过这个命令,你可以非常灵活的对线上机器通过固定频率输出统计信息,观察每隔一段时间的jvm中的Eden区对象占 用变化。
举例

        执行这个命令之后,第一秒先显示出来Eden区使用了200MB内存,第二秒显示出来的那行统计信息里,发现Eden区使用了205MB内存,第三秒显示出来的那行统计信息里,发现Eden区使用了209MB内存,以此类推。
        此时你可以轻易的推断出来,这个系统大概每秒钟会新增5MB左右的对象。

可以根据自己系统的情况灵活多变的使用,比如你们系统负载很低,不一定每秒都有请求,那么可以把上面的1秒钟调整为1分钟甚至10分钟,去看你们系统每隔1分钟或者10分钟大概增长多少对象
        一般系统都有高峰和日常两种状态,比如系统高峰期用的人很多,此时你就应该在系统高峰期去用上述命令看看高峰期的对象增长速率。然后你再得在非高峰的日常时间段内看看对象的增长速率。

        按照上述思路,基本上你可以对线上系统的高峰和日常两个时间段内的对象增长速率有很清晰的了解。

4.2、Young GC的触发频率和每次耗时

        多久触发一次Young GC很容易推测出来,因为系统高峰和日常时候的对象增长速率你都知道了,那么非常简单就可以推测出来高峰期多久发生一次Young GC,日常期多久发生一次Young GC。

举例:
**        **你Eden区有800MB内存,那么发现高峰期每秒新增5MB对象,大概高峰期就是3分钟会触发一次Young GC。日常期每秒新增0.5MB对象,那么日常期大概需要半个小时才会触发一次Young GC。

那么每次Young GC的平均耗时呢?
        jstat会告诉你迄今为止系统已经发生了多少次Young GC以及这些Young GC的总耗时

比如系统运行24小时后共发生了260次Young GC,总耗时为20s。那么平均下来每次Young GC大概就耗时几十毫秒的时间。
        你大概就知道每次Young GC的时候会导致系统停顿几十毫秒。

4.3、每次Young GC后有多少对象是存活和进入老年代

         每次Young GC过后有多少对象会存活下来,这个没法直接看出来,但是有办法可以大致推测出来。

        之前我们已经推算出来高峰期的时候多久发生一次Young GC,比如3分钟会有一次Young GC
那么此时我们可以执行下述jstat命令:jstat -gc PID 180000 10。这就相当于是让他每隔三分钟执行一次统计,连续执行10次。

        此时大家可以观察一下,每隔三分钟之后发生了一次Young GC,此时Eden、Survivor、老年代的对象变化。
        正常来说,Eden区肯定会在几乎放满之后重新变得里面对象很少,比如800MB的空间就使用了几十MB。Survivor区肯定会放入一些存活对象,老年代可能会增长一些对象占用。所以这里的关键,就是观察老年代的对象增长速率。

        从一个正常的角度来看,老年代的对象是不太可能不停的快速增长的,因为普通的系统其实没那么多长期存活的对象。如果你发现比如每次Young GC过后,老年代对象都要增长几十MB,那很有可能就是你一次Young GC过后存活对象太多了。存活对象太多,可能导致放入Survivor区域之后触发了动态年龄判定规则进入老年代,也可能是Survivor区域放不下了,所以大部分存活对象进入老年代。
        最常见的就是这种情况。如果你的老年代每次在Young GC过后就新增几百KB,或者几MB的对象,这个还算情有可原,但是如果老年代对象快速增长,那一定是不正常的。

        所以通过上述观察策略,你就可以知道每次Young GC过后多少对象是存活的,实际上Survivor区域里的和进入老年代的对象,都是存活的。
        你也可以知道老年代对象的增长速率,比如每隔3分钟一次Young GC,每次会有50MB对象进入老年代,这就是年代对象的增长速率,每隔3分钟增长50MB。

4.4、Full GC的触发时机和耗时

        只要知道了老年代对象的增长速率,那么Full GC的触发时机就很清晰了。比如老年代总共有800MB的内存,每隔3分钟新增50MB对象,那么大概每小时就会触发一次Full GC。
        然后可以看到jstat打印出来的系统运行起劲为止的Full GC次数以及总耗时,比如一共执行了10次Full GC,共耗时30s,每次Full GC大概就是需要耗费3s左右。

5、其他可视化工具

        比如JConsole、VisualVM等可视化的监控工具,还有其他一些开源的监控系统,都是可视化的。

6、案例实战

6.1、模拟代码的JVM参数设置

接着我们会用一段程序来模拟出那种频繁Young GC的一个场景,此时JVM参数如下所示:

-XX:NewSize=104857600 -XX:MaxNewSize=104857600 -XX:InitialHeapSize=209715200 
-XX:MaxHeapSize=209715200 -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=15 
-XX:PretenureSizeThreshold=3145728 -XX:+UseParNewGC 
-XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps 
-Xloggc:gc.log

大家只要注意一下上述我们把堆内存设置为了200MB,把年轻代设置为了100MB,然后Eden区是80MB,每块Survivor区是10MB,老年代也是100MB。

6.2、示例程序

public class Demo1 {
    public static void main(String[] args) {

        try {
            Thread.sleep(30000);
            while(true){
                loadData();
            }
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

    }

    public static void loadData() throws InterruptedException {
        byte[] bytes = null;
        for (int i = 0; i < 50; i++) {
            bytes = new byte[100 * 1024];
        }
        bytes = null;
        Thread.sleep(1000);
    }
}

为什么刚开始先休眠30s?

        因为一会儿会告诉大家,程序刚启动,必须得先让我们找到这个程序的PID,也就是进程ID,然后再执行jstat命令来观察程序运行时JVM的状态。

loadData()方法内的代码?
        他会循环50次,模拟每秒50个请求然后每次请求会分配一个100KB的数组,模拟每次请求会从数据存储中加载出来100KB的数据。接着会休眠1秒钟,模拟这一切都是发生在1秒内的。

        其实这些对象都是短生存周期的对象,所以方法运行结束直接对象都是垃圾,随时可以回收的。然后在main()方法里有一个while(true)循环,模拟系统按照每秒钟50个请求,每个请求加载100KB数据的方式不停的运行,除非我们手动终止程序,否则永不停歇。

6.3**、通过jstat观察程序的运行状态**

使用预订的JVM参数启动程序,此时程序会先进入一个30秒的休眠状态,此时尽快执行jps命令,查看一下我们启动程序的进程ID
此时会发现我们运行的Demo1这个程序的JVM进程ID是7968。

然后尽快执行下述jstat命令**:**
jstat -gc 7968 1000 1000

他的意思就是针对7968这个进程统计JVM运行状态,同时每隔1秒钟打印一次统计信息,连续打印1000次。 然后我们就让jstat开始统计运行,每隔一秒他都会打印一行新的统计信息,过了几十秒后可以看到如下图所示的统计信息:

 注意看上面红圈里的内容,大家会发现,Eden区的使用量从70多MB降低为了0,这就是因为一次Young GC直接回收掉了对象。
所以我们现在就知道了,针对这个代码示例,可以清晰的从jstat中看出来,对象增速大致为每秒5MB左右,大致在十几秒左右会触发一 次Young GC .这个就是Young GC的触发频率,以及每次Young GC的耗时

        一次Young GC回收70多MB对象,大概就1毫秒,所以大家想想,Young GC其实是很快的,即使回收800MB的对象,也就10毫秒那样。所以你想如果是线上系统,他Eden区800MB的话,每秒新增对象50MB,十多秒一次Young GC,也就10毫秒左右,系统卡顿10毫 秒,几乎没什么大影响的。

所以我们继续推论,在这个示例中,80MB的Eden区,每秒新增对象5MB,大概十多秒触发一次Young GC,每次Young GC耗时在1 毫秒左右。

那么每次Young GC过后存活的对象呢?
简单看上上图,S1U就是Survivor中被使用的内存,之前一直是0,在一次Young GC过后变成了887KB,所以一次Young GC后也就存 活887KB的对象而已,轻松放入10MB的Survivor中。

而且大家注意上上图中的OU,那是老年代被使用的内存量,在Young GC前后都是0 。这说明这个系统运行良好,Young GC都不会导致对象进入老年代,这就几乎不需要什么优化了。因为几乎可以默认老年代对象增速为 0,Full GC发生频率趋向于0,对系统无影响。

相关文章