JVM性能调优 —— 利用工具调优分析问题

 2023-01-18
原文作者:bojiangzhou 原文地址:https://juejin.cn/post/6921527104009928717

系列文章专栏:JVM系列专栏

利用工具分析JVM运行情况

要想合理地分配内存、优化GC,通过前一篇的性能调优过程可以发现,我们至少需要知道如下的一些信息:新生代对象增长的速率,YoungGC的触发频率,YoungGC的耗时,每次YoungGC后存活对象大小,每次YoungGC过后有多少对象进入了老年代,老年代对象增长的速率,FullGC的触发频率,FullGC的耗时等。前面我们是通过分析GC日志或者粗略估算的方式来调优的,现在就利用 jstat 工具来分析下。

运行示例程序

1、如下示例代码

这段代码模拟每秒钟在新生代创建20M对象,1秒之后就变为垃圾对象了。

    public class GCMain {
        static final int _1M = 1024 * 1024;
    
        public static void main(String[] args) {
            sleep(20);
    
            for (int i = 0; i < 100; i++) {
                loadData(i);
            }
        }
    
        // loadData 每次请求产生20M对象,每次请求耗时1秒
        public static void loadData(int index) {
            System.out.println("load data: " + index);
            byte[] data1 = new byte[_1M * 10];
            byte[] data2 = new byte[_1M * 10];
    
            sleep(1);
        }
    
        public static void sleep(long seconds) {
            try {
                Thread.sleep(seconds * 1000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }

2、设置JVM参数

运行示例程序前设置如下的JVM参数:新生代、老年代各100M,Eden区80M,Survivor区10M,大对象阀值20M。

    -Xms200M
    -Xmx200M
    -Xmn100M
    -XX:SurvivorRatio=8
    -XX:MaxTenuringThreshold=5
    -XX:PretenureSizeThreshold=20M
    -XX:+UseParNewGC
    -XX:+UseConcMarkSweepGC
    -XX:CMSInitiatingOccupancyFraction=92
    -XX:+UseCMSInitiatingOccupancyOnly
    -XX:+UseCMSCompactAtFullCollection
    -XX:CMSFullGCsBeforeCompaction=0
    -XX:+PrintGC
    -XX:+PrintGCDetails
    -XX:+PrintGCDateStamps
    -Xloggc:./gc.log

3、估算内存运转模型

我们先根据这段业务代码以及JVM参数配置估算下JVM运行情况:

  • 这段代码每秒将在Eden区产生20M对象,大概3~4秒钟会占满Eden区触发YoungGC。
  • YoungGC 后存活的对象可能超过10M,因为可能在创建 data2 时,Eden区不够了,而 data1 还是存活的;也有可能为0,在创建 data1 的时候 Eden 区就不够了。
  • 由于 Survivor 区不足以放下YoungGC后存活的对象,那么每次大概会有10M的对象进入老年代;考虑到有可能YoungGC后没有存活对象,就估算为2次YoungGC会有10M进入老年代吧。
  • YoungGC 3~4 秒触发一次,那么大概经过18次左右YoungGC,就是60秒左右,老年代就快满了,然后存活对象无法放入老年代触发FullGC。
  • 由于CMS后台回收线程在老年代超过92%时会触发OldGC,所以60秒左右也有可能由于老年代超过92%这个阀值触发GC。

4、使用 jps 命令找出程序的 PID

将程序运行起来,首先通过 jps -l 命令找到这个程序的PID。

202301011642227361.png

5、使用 jstat 命令查看GC情况

如下是 jstat 输出的情况:

    Mechrevo@hello-world MINGW64 ~/Desktop
    $ jstat -gc 15488 1000 1000
     S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
    10240.0 10240.0  0.0    0.0   81920.0   4984.1   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
    10240.0 10240.0  0.0    0.0   81920.0   4984.1   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
    10240.0 10240.0  0.0    0.0   81920.0   4984.1   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
    10240.0 10240.0  0.0    0.0   81920.0   4984.1   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
    10240.0 10240.0  0.0    0.0   81920.0   4984.1   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
    10240.0 10240.0  0.0    0.0   81920.0  25464.1   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
    10240.0 10240.0  0.0    0.0   81920.0  45944.2   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
    10240.0 10240.0  0.0    0.0   81920.0  66424.2   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
    10240.0 10240.0  0.0   713.8  81920.0  11878.4   102400.0   10242.1   4864.0 3043.9 512.0  321.7       1    0.005   0      0.000    0.005
    10240.0 10240.0  0.0   713.8  81920.0  33961.9   102400.0   10242.1   4864.0 3043.9 512.0  321.7       1    0.005   0      0.000    0.005
    10240.0 10240.0  0.0   713.8  81920.0  54441.9   102400.0   10242.1   4864.0 3043.9 512.0  321.7       1    0.005   0      0.000    0.005
    10240.0 10240.0  0.0   713.8  81920.0  74922.0   102400.0   10242.1   4864.0 3043.9 512.0  321.7       1    0.005   0      0.000    0.005
    10240.0 10240.0 828.5   0.0   81920.0  22891.3   102400.0   10242.1   4864.0 3044.4 512.0  321.7       2    0.005   0      0.000    0.005
    10240.0 10240.0 828.5   0.0   81920.0  43371.3   102400.0   10242.1   4864.0 3044.4 512.0  321.7       2    0.005   0      0.000    0.005
    10240.0 10240.0 828.5   0.0   81920.0  63851.3   102400.0   10242.1   4864.0 3044.4 512.0  321.7       2    0.005   0      0.000    0.005
    10240.0 10240.0  0.0   964.7  81920.0  10240.0   102400.0   20484.1   4864.0 3044.5 512.0  321.7       3    0.010   0      0.000    0.010
    10240.0 10240.0  0.0   964.7  81920.0  32230.5   102400.0   20484.1   4864.0 3044.5 512.0  321.7       3    0.010   0      0.000    0.010
    10240.0 10240.0  0.0   964.7  81920.0  52710.5   102400.0   20484.1   4864.0 3044.5 512.0  321.7       3    0.010   0      0.000    0.010
    10240.0 10240.0  0.0   964.7  81920.0  73190.5   102400.0   20484.1   4864.0 3044.5 512.0  321.7       3    0.010   0      0.000    0.010
    10240.0 10240.0 759.6   0.0   81920.0  22035.2   102400.0   20484.1   4864.0 3044.5 512.0  321.7       4    0.011   0      0.000    0.011
    10240.0 10240.0 759.6   0.0   81920.0  42515.2   102400.0   20484.1   4864.0 3044.5 512.0  321.7       4    0.011   0      0.000    0.011
    10240.0 10240.0 759.6   0.0   81920.0  62995.2   102400.0   20484.1   4864.0 3044.5 512.0  321.7       4    0.011   0      0.000    0.011
    10240.0 10240.0  0.0   886.2  81920.0  10240.0   102400.0   30724.1   4864.0 3044.5 512.0  321.7       5    0.016   0      0.000    0.016
    10240.0 10240.0  0.0   886.2  81920.0  32212.1   102400.0   30724.1   4864.0 3044.5 512.0  321.7       5    0.016   0      0.000    0.016
    10240.0 10240.0  0.0   886.2  81920.0  52692.1   102400.0   30724.1   4864.0 3044.5 512.0  321.7       5    0.016   0      0.000    0.016
    10240.0 10240.0  0.0   886.2  81920.0  73172.1   102400.0   30724.1   4864.0 3044.5 512.0  321.7       5    0.016   0      0.000    0.016
    10240.0 10240.0  0.0    0.0   81920.0  22023.2   102400.0   31373.1   4864.0 3044.5 512.0  321.7       6    0.019   0      0.000    0.019
    10240.0 10240.0  0.0    0.0   81920.0  42503.3   102400.0   31373.1   4864.0 3044.5 512.0  321.7       6    0.019   0      0.000    0.019
    10240.0 10240.0  0.0    0.0   81920.0  62983.3   102400.0   31373.1   4864.0 3044.5 512.0  321.7       6    0.019   0      0.000    0.019
    10240.0 10240.0  0.0    0.0   81920.0  10240.0   102400.0   41613.1   4864.0 3044.5 512.0  321.7       7    0.024   0      0.000    0.024
    10240.0 10240.0  0.0    0.0   81920.0  32204.4   102400.0   41613.1   4864.0 3044.5 512.0  321.7       7    0.024   0      0.000    0.024
    10240.0 10240.0  0.0    0.0   81920.0  52684.4   102400.0   41613.1   4864.0 3044.5 512.0  321.7       7    0.024   0      0.000    0.024
    10240.0 10240.0  0.0    0.0   81920.0  73164.4   102400.0   41613.1   4864.0 3044.5 512.0  321.7       7    0.024   0      0.000    0.024
    10240.0 10240.0  0.0    0.0   81920.0  22018.2   102400.0   41613.1   4864.0 3044.9 512.0  321.7       8    0.025   0      0.000    0.025
    10240.0 10240.0  0.0    0.0   81920.0  42498.3   102400.0   41613.1   4864.0 3044.9 512.0  321.7       8    0.025   0      0.000    0.025
    10240.0 10240.0  0.0    0.0   81920.0  62978.3   102400.0   41613.1   4864.0 3044.9 512.0  321.7       8    0.025   0      0.000    0.025
    10240.0 10240.0  0.0    0.0   81920.0  10240.0   102400.0   51853.2   4864.0 3044.9 512.0  321.7       9    0.030   0      0.000    0.030
    10240.0 10240.0  0.0    0.0   81920.0  32201.1   102400.0   51853.2   4864.0 3044.9 512.0  321.7       9    0.030   0      0.000    0.030
    10240.0 10240.0  0.0    0.0   81920.0  52681.2   102400.0   51853.2   4864.0 3044.9 512.0  321.7       9    0.030   0      0.000    0.030
    10240.0 10240.0  0.0    0.0   81920.0  73161.2   102400.0   51853.2   4864.0 3044.9 512.0  321.7       9    0.030   0      0.000    0.030
    10240.0 10240.0  0.0    0.0   81920.0  22016.1   102400.0   51853.2   4864.0 3045.6 512.0  321.7      10    0.031   0      0.000    0.031
    10240.0 10240.0  0.0    0.0   81920.0  42496.2   102400.0   51853.2   4864.0 3045.6 512.0  321.7      10    0.031   0      0.000    0.031
    10240.0 10240.0  0.0    0.0   81920.0  62976.2   102400.0   51853.2   4864.0 3045.6 512.0  321.7      10    0.031   0      0.000    0.031
    10240.0 10240.0  0.0    0.0   81920.0  10240.0   102400.0   62093.2   4864.0 3045.9 512.0  321.7      11    0.036   0      0.000    0.036
    10240.0 10240.0  0.0    0.0   81920.0  32199.8   102400.0   62093.2   4864.0 3045.9 512.0  321.7      11    0.036   0      0.000    0.036
    10240.0 10240.0  0.0    0.0   81920.0  52679.8   102400.0   62093.2   4864.0 3045.9 512.0  321.7      11    0.036   0      0.000    0.036
    10240.0 10240.0  0.0    0.0   81920.0  52679.8   102400.0   62093.2   4864.0 3045.9 512.0  321.7      11    0.036   0      0.000    0.036
    10240.0 10240.0  0.0    0.0   81920.0  22015.3   102400.0   62093.2   4864.0 3045.9 512.0  321.7      12    0.036   0      0.000    0.036
    10240.0 10240.0  0.0    0.0   81920.0  42495.3   102400.0   62093.2   4864.0 3045.9 512.0  321.7      12    0.036   0      0.000    0.036
    10240.0 10240.0  0.0    0.0   81920.0  62975.3   102400.0   62093.2   4864.0 3045.9 512.0  321.7      12    0.036   0      0.000    0.036
    10240.0 10240.0  0.0    0.0   81920.0    0.0     102400.0   72333.2   4864.0 3045.9 512.0  321.7      13    0.041   0      0.000    0.041
    10240.0 10240.0  0.0    0.0   81920.0  32199.2   102400.0   72333.2   4864.0 3045.9 512.0  321.7      13    0.041   0      0.000    0.041
    10240.0 10240.0  0.0    0.0   81920.0  52679.3   102400.0   72333.2   4864.0 3045.9 512.0  321.7      13    0.041   0      0.000    0.041
    10240.0 10240.0  0.0    0.0   81920.0  74797.7   102400.0   72333.2   4864.0 3045.9 512.0  321.7      13    0.041   0      0.000    0.041
    10240.0 10240.0  4.0    0.0   81920.0    0.0     102400.0   72333.2   4864.0 3048.0 512.0  321.7      14    0.042   0      0.000    0.042
    10240.0 10240.0  4.0    0.0   81920.0  22014.9   102400.0   72333.2   4864.0 3048.0 512.0  321.7      14    0.042   0      0.000    0.042
    10240.0 10240.0  4.0    0.0   81920.0  62975.0   102400.0   72333.2   4864.0 3048.0 512.0  321.7      14    0.042   0      0.000    0.042
    10240.0 10240.0  0.0    2.0   81920.0  10240.0   102400.0   82573.2   4864.0 3048.0 512.0  321.7      15    0.047   0      0.000    0.047
    10240.0 10240.0  0.0    2.0   81920.0  10240.0   102400.0   82573.2   4864.0 3048.0 512.0  321.7      15    0.047   0      0.000    0.047
    10240.0 10240.0  0.0    2.0   81920.0  32199.0   102400.0   82573.2   4864.0 3048.0 512.0  321.7      15    0.047   0      0.000    0.047
    10240.0 10240.0  0.0    2.0   81920.0  73159.1   102400.0   82573.2   4864.0 3048.0 512.0  321.7      15    0.047   0      0.000    0.047
    10240.0 10240.0  4.0    0.0   81920.0    0.0     102400.0   82573.2   4864.0 3048.0 512.0  321.7      16    0.048   0      0.000    0.048
    10240.0 10240.0  4.0    0.0   81920.0  22014.7   102400.0   82573.2   4864.0 3048.0 512.0  321.7      16    0.048   0      0.000    0.048
    10240.0 10240.0  4.0    0.0   81920.0  62974.8   102400.0   82573.2   4864.0 3048.0 512.0  321.7      16    0.048   0      0.000    0.048
    10240.0 10240.0  0.0    2.0   81920.0  10240.0   102400.0   10892.1   4864.0 3048.7 512.0  321.7      17    0.053   2      0.002    0.055
    10240.0 10240.0  0.0    2.0   81920.0  10240.0   102400.0   10892.1   4864.0 3048.7 512.0  321.7      17    0.053   2      0.002    0.055
    10240.0 10240.0  0.0    2.0   81920.0  32198.9   102400.0   10892.1   4864.0 3048.7 512.0  321.7      17    0.053   2      0.002    0.055
    10240.0 10240.0  0.0    2.0   81920.0  73159.0   102400.0   10892.1   4864.0 3048.7 512.0  321.7      17    0.053   2      0.002    0.055
    10240.0 10240.0  2.0    0.0   81920.0  22833.9   102400.0   10892.1   4864.0 3049.0 512.0  321.7      18    0.054   2      0.002    0.056
    10240.0 10240.0  2.0    0.0   81920.0  22833.9   102400.0   10892.1   4864.0 3049.0 512.0  321.7      18    0.054   2      0.002    0.056
    10240.0 10240.0  2.0    0.0   81920.0  43313.9   102400.0   10892.1   4864.0 3049.0 512.0  321.7      18    0.054   2      0.002    0.056
    10240.0 10240.0  0.0    4.0   81920.0    0.0     102400.0   21132.1   4864.0 3049.0 512.0  321.7      19    0.056   2      0.002    0.058
    10240.0 10240.0  0.0    4.0   81920.0  10240.0   102400.0   21132.1   4864.0 3049.0 512.0  321.7      19    0.056   2      0.002    0.058
    10240.0 10240.0  0.0    4.0   81920.0  32193.5   102400.0   21132.1   4864.0 3049.0 512.0  321.7      19    0.056   2      0.002    0.058
    10240.0 10240.0  0.0    4.0   81920.0  52673.6   102400.0   21132.1   4864.0 3049.0 512.0  321.7      19    0.056   2      0.002    0.058
    10240.0 10240.0  2.0    0.0   81920.0  22011.2   102400.0   21132.1   4864.0 3049.0 512.0  321.7      20    0.057   2      0.002    0.058
    10240.0 10240.0  2.0    0.0   81920.0  22011.2   102400.0   21132.1   4864.0 3049.0 512.0  321.7      20    0.057   2      0.002    0.058
    10240.0 10240.0  2.0    0.0   81920.0  42491.2   102400.0   21132.1   4864.0 3049.0 512.0  321.7      20    0.057   2      0.002    0.058
    10240.0 10240.0  0.0    4.0   81920.0    0.0     102400.0   31372.2   4864.0 3049.0 512.0  321.7      21    0.059   2      0.002    0.060
    10240.0 10240.0  0.0    4.0   81920.0  10240.0   102400.0   31372.2   4864.0 3049.0 512.0  321.7      21    0.059   2      0.002    0.060
    10240.0 10240.0  0.0    4.0   81920.0  32196.6   102400.0   31372.2   4864.0 3049.0 512.0  321.7      21    0.059   2      0.002    0.060
    10240.0 10240.0  0.0    4.0   81920.0  52676.6   102400.0   31372.2   4864.0 3049.0 512.0  321.7      21    0.059   2      0.002    0.060
    10240.0 10240.0  4.0    0.0   81920.0    0.0     102400.0   31372.2   4864.0 3049.0 512.0  321.7      22    0.059   2      0.002    0.061
    10240.0 10240.0  4.0    0.0   81920.0  22013.2   102400.0   31372.2   4864.0 3049.0 512.0  321.7      22    0.059   2      0.002    0.061
    10240.0 10240.0  4.0    0.0   81920.0  42493.2   102400.0   31372.2   4864.0 3049.0 512.0  321.7      22    0.059   2      0.002    0.061
    10240.0 10240.0  0.0    4.0   81920.0    0.0     102400.0   41612.2   4864.0 3049.0 512.0  321.7      23    0.061   2      0.002    0.062
    10240.0 10240.0  0.0    4.0   81920.0  10240.0   102400.0   41612.2   4864.0 3049.0 512.0  321.7      23    0.061   2      0.002    0.062
    10240.0 10240.0  0.0    4.0   81920.0  32197.9   102400.0   41612.2   4864.0 3049.0 512.0  321.7      23    0.061   2      0.002    0.062
    10240.0 10240.0  0.0    4.0   81920.0  52677.9   102400.0   41612.2   4864.0 3049.0 512.0  321.7      23    0.061   2      0.002    0.062
    10240.0 10240.0  0.0    0.0   81920.0    0.0     102400.0   41612.2   4864.0 3049.0 512.0  321.7      24    0.061   2      0.002    0.063
    10240.0 10240.0  0.0    0.0   81920.0  42494.1   102400.0   41612.2   4864.0 3049.0 512.0  321.7      24    0.061   2      0.002    0.063
    10240.0 10240.0  0.0    0.0   81920.0  42494.1   102400.0   41612.2   4864.0 3049.0 512.0  321.7      24    0.061   2      0.002    0.063
    10240.0 10240.0  0.0    0.0   81920.0    0.0     102400.0   51852.3   4864.0 3049.8 512.0  321.7      25    0.063   2      0.002    0.065
    10240.0 10240.0  0.0    0.0   81920.0  10240.0   102400.0   51852.3   4864.0 3049.8 512.0  321.7      25    0.063   2      0.002    0.065
    10240.0 10240.0  0.0    0.0   81920.0  32198.4   102400.0   51852.3   4864.0 3049.8 512.0  321.7      25    0.063   2      0.002    0.065
    10240.0 10240.0  0.0    0.0   81920.0  52678.5   102400.0   51852.3   4864.0 3049.8 512.0  321.7      25    0.063   2      0.002    0.065
    10240.0 10240.0  0.0    0.0   81920.0    0.0     102400.0   51852.3   4864.0 3049.8 512.0  321.7      26    0.064   2      0.002    0.065
    10240.0 10240.0  0.0    0.0   81920.0  22014.4   102400.0   51852.3   4864.0 3049.8 512.0  321.7      26    0.064   2      0.002    0.065
    10240.0 10240.0  0.0    0.0   81920.0  42494.4   102400.0   51852.3   4864.0 3049.8 512.0  321.7      26    0.064   2      0.002    0.065
    10240.0 10240.0  0.0    0.0   81920.0  62974.4   102400.0   51852.3   4864.0 3049.8 512.0  321.7      26    0.064   2      0.002    0.065
    10240.0 10240.0  0.0    0.0   81920.0  10240.0   102400.0   62092.3   4864.0 3049.8 512.0  321.7      27    0.065   2      0.002    0.067
    10240.0 10240.0  0.0    0.0   81920.0  32198.7   102400.0   62092.3   4864.0 3049.8 512.0  321.7      27    0.065   2      0.002    0.067
    10240.0 10240.0  0.0    0.0   81920.0  52678.7   102400.0   62092.3   4864.0 3049.8 512.0  321.7      27    0.065   2      0.002    0.067
    10240.0 10240.0  0.0    0.0   81920.0  73158.7   102400.0   62092.3   4864.0 3049.8 512.0  321.7      27    0.065   2      0.002    0.067
    10240.0 10240.0  0.0    0.0   81920.0  22014.5   102400.0   62092.3   4864.0 3050.1 512.0  321.7      28    0.066   2      0.002    0.068
    10240.0 10240.0  0.0    0.0   81920.0  42494.6   102400.0   62092.3   4864.0 3050.1 512.0  321.7      28    0.066   2      0.002    0.068

首先从前面几行可以看出内存各个区域的大小,Survivor0/Survivor1 10M,Eden区80M,老年代100M 等信息。

202301011642233022.png

新生代对象增长的速率

从 EU 这一行可以看出,新生代基本是按照每秒20M左右的对象在增长。

202301011642242433.png

YoungGC的触发频率和耗时

从 Eden 区的内存变化可以看出,基本是每隔3秒或4秒就会触发一次 YoungGC,比如第一次Eden区增长到66424.2时,经过一次 YoungGC后只剩下11878.4。从 YGC 这列也大致可以看出YoungGC的频率。

从 YGCT 这列可以看出,每次YoungGC耗时1~5毫秒的样子,也就是说每隔3~4秒,触发一次YoungGC,一次YoungGC系统卡顿1~5毫秒。这也可以看出 YoungGC 其实是很快的,就算新生代800M也才10几毫秒,对系统几乎没什么影响。

202301011642250834.png

YoungGC后存活对象大小以及有多少对象进入了老年代

S0U、S1U 这两列的变化可以看出,每次YoungGC后有800K左右的对象进入 Survivor 区。

OU 这列的变化可以看出,每次进入老年代的对象在10M左右,所以一次YoungGC后可能有10M的存活对象进入老年代。

202301011642257025.png

FullGC的触发频率和耗时

OU 这列的变化可以看出,在老年代达到 82573.2 时,触发了 FullGC,回收后老年代大小为 10892.1。从整体的时间线上看,刚好60秒就触发了一次FullGC。

FGCT 可以看出,一次 FullGC 耗时2毫秒:

202301011642266946.png

为什么在老年代 82573.2 时就触发了FullGC 呢,我们从GC日志中来看:

202301011642277567.png

可以看出这一秒内,实际上这次 YoungGC 导致有10M的对象进入老年代,老年代实际有92815K对象,因而应该是CMS超过了 92% 的阀值之后触发了老年代GC。

使用GCeasy查看GC日志

至此,其实已经基本上分析出整个JVM的运转情况了。这里总结下:

  • 新生代、老年代 100M,Eden区80M,Survivor区10M;
  • Eden区每秒产生20M左右对象,每隔3~4秒触发一次YoungGC;
  • YoungGC后存活对象在0~10M左右,由于无法放入Survivor区会进入老年代,每次进入老年代对象10M左右;
  • 在经过16次左右YoungGC后,也就是60秒左右老年代会接近占满,超过设置的阀值,触发一次 FullGC。

从上面的分析可以看出,jstat 监控的输出结果基本是符合前面估算的结果的。但是粗略估算需要熟悉系统核心的业务,而且其它未知因素也比较多,粗略估算一般用于系统刚上线阶段来设置JVM参数。而通过 jstat 来监控一般就可以比较准确的摸清JVM的运行情况,然后进行性能调优。

接下来再通过GC日志来看下是否符合分析的情况,GC日志就不再一行一行分析了,我们直接通过在线工具 GCeasy 来看看内存变化和GC的情况。将输出的GC日志直接拷贝到 GCeasy 上,就可以看到分析的结果。

1、GC总体情况

从这张图可以得到如下信息:

  • 垃圾回收器的吞吐率为 99.937%;
  • 平均GC停顿时间:2毫秒
  • 最长GC停顿时间:10毫秒
  • 80% 的GC耗时 0~1毫秒
  • 20% 的GC耗时 9~10毫秒

202301011642284228.png

2、YoungGC频率

Young Gen 这个统计图可以看出,YoungGC的频率在3~4秒的样子。

202301011642294979.png

3、老年代GC频率

从这张统计图可以看出,老年代是每两次YoungGC增长一次,每次增长10M左右,在60秒左右触发一次OldGC。

2023010116423045610.png

4、CMS回收情况

这张图展示了CMS各个阶段的统计情况

2023010116423105311.png

性能优化

从上面的分析可以看出,这个JVM最大的问题在于 Survivor 区没起作用,Survivor 区只有10M,而YoungGC后存活对象大于10M,导致无法放进Survivor区而直接进入老年代了,进而触发FullGC。因此我们可以增大新生代大小或者调整Eden区和Survivor区比例,来让对象进入Survivor区。

比如改为如下配置:新生代给150M,比例调整为6,这样Eden区90M,Survivor区各30M,这样Survivor区足以放下YoungGC后存活的对象,也基本上能避免动态年龄判断导致对象进入老年代。

    -Xms200M
    -Xmx200M
    -Xmn150M
    -XX:SurvivorRatio=6

再看这时的GC情况,首先从 S0U、S1U 的变化可以看出,Survivor 区在起作用了,每次YoungGC后存活对象都进入Survivor区了。

然后从 OU、YGC 的变化可以看出,有部分长期存活的对象在 YoungGC 次数超过设置的GC年龄阀值(设置的5岁)后,进入了老年代。

从 FGC 这列可以看出,Survivor 区合理设置后,再没有发生过 FullGC 了。

2023010116423188112.png

使用 MAT 分析OOM问题

对于排查 OOM 问题、分析程序堆内存使用情况,最好的方式就是分析堆转储,堆转储,包含了堆现场全貌和线程栈信息。这节就来看看如何使用MAT分析OOM问题。

运行示例程序

准备如下两个测试类:

    package com.lyyzoo.test.jvm;
    
    public class OomService {
    
        private List<String> data = new ArrayList<>();
    
        public void addData() {
            //往同一个ArrayList中不断加入大小为10KB的字符串
            data.add(IntStream.rangeClosed(1, 10_000)
                    .mapToObj(__ -> "A")
                    .collect(Collectors.joining("")));
        }
    }
    package com.lyyzoo.test.jvm;
    
    public class OomMain {
        public static void main(String[] args) {
            OomService service = new OomService();
    
            while (true) {
                service.addData();
            }
        }
    }

设置如下JVM参数:

    -Xms200M
    -Xmx200M
    -Xmn100M
    -XX:+HeapDumpOnOutOfMemoryError
    -XX:HeapDumpPath=./dump.hprof
    -XX:+PrintGC
    -XX:+PrintGCDetails
    -XX:+PrintGCDateStamps
    -Xloggc:./gc.log

运行程序后报OOM异常:

2023010116423273713.png

MAT 分析OOM问题的思路

对于线上运行的程序,如果我们不能通过日志快速定位出OOM的根源,一般就可以使用MAT来分析OOM的问题。

使用 MAT 分析 OOM 问题,一般可以按照以下思路进行:

  • 通过支配树功能或直方图功能查看消耗内存最大的类型,来分析内存泄露的大概原因;
  • 查看那些消耗内存最大的类型、详细的对象明细列表,以及它们的引用链,来定位内存泄露的具体点;
  • 配合查看对象属性的功能,可以脱离源码看到对象的各种属性的值和依赖关系,帮助我们理清程序逻辑和参数;
  • 辅助使用查看线程栈来看 OOM 问题是否和过多线程有关,甚至可以在线程栈看到 OOM 最后一刻出现异常的线程。

如果dump出来的内存快照很大,比如有几个G,务必在启动MAT之前,先在配置文件(MemoryAnalyzer.ini)里给MAT本身设置—下堆内存大小(默认为1024m),比如设置为4个G,或者8个G。

总览图 — 快速分析OOM问题

使用MAT打开堆转储文件 dump.hprof,打开后先进入的是概览信息界面:

从饼图可以看出,明显有对象占用了大量内存,然后再看 Problem Suspect1 ,已经说明了 main 线程通过局部变量占据了 99.42% 内存的对象,而且是 java.lang.Object[] 数组占据了大量内存。

2023010116423371814.png

点击 Details 进去查看详细的说明,从 “Accumulated Objects in Dominator Tree” 支配树可以看出,main 线程引用了 OomService 对象,OomService 引用了一个 ArrayList 对象,然后 ArrayList 存储了大量 String 对象。这里基本上就能分析出OOM的根源了。

2023010116423428615.png

再点击 See stacktrace 看看线程栈基本就能定位到问题代码了。

2023010116423517016.png

直方图 — 定位根源

工具栏的第二个按钮可以打开直方图,直方图按照类型进行分组,列出了每个类有多少个实例,以及占用的内存。

可以看到,char[] 字节数组占用内存最多,对象数量也很多,第二位的 String 对象数量也非常多,有 9791 个,从这大概可以猜出应该是创建了大量的 String 对象。

2023010116423615617.png

char[] 上点击右键,选择 List objects -> with incoming references,就可以列出所有的 char[] 实例,以及每个 char[] 的整个引用关系链:

2023010116423688018.png

随机展开一个 char[],如下图所示:

右侧框中可以看到整个引用链,左侧的框可以查看每一个实例的内部属性。

通过这个引用链可以发现是 String 对象引用了 char[] 数组(String 的内部结构就是一个 char[] 数组),说明创建了大量的 String 对象;然后 String 对象又被 ArrayList 的 Object[] 数组引用着,说明是大量 String 对象放入了 ArrayList 中,然后这个 ArrayList 又被 OomService 的 data 变量引用着。到这里就定位出了引发OOM的类了。

Retained Heap(深堆) 代表对象本身和对象关联的对象占用的内存, Shallow Heap(浅堆) 代表对象本身占用的内存。比如,OomService 中的 data 这个 ArrayList 对象本身只有 16 字节,但是其所有关联的对象占用了 130+MB 内存。

2023010116423785119.png

如果希望看到完整内容的话,可以右键选择 Copy->Value,把值复制到剪贴板或保存到文件中:

2023010116423886520.png

支配树 — 定位根源

其实,使用直方图定位 OomService,已经走了些弯路。可以点击工具栏中第三个按钮进入支配树界面。这个界面会按照对象保留的 Retained Heap 倒序直接列出占用内存最大的对象。

可以看到,第一位就是 OomService,整个路径是 OomSerice -> ArrayList -> Object[] -> String -> char[]

2023010116423945421.png

线程栈 — 分析代码

可以点击工具栏的第五个按钮,打开线程视图来分析 OomService 执行什么逻辑。可以看到 OomService 是 OomMain 的一个本地变量,然后 OomMain 调用了 OomService 的 addData 方法,然后 addData 方法里应该是通过 Stream 生成一个字符串放入 data 中的。

2023010116424036022.png

OQL—查询数据

点击工具栏的第四个按钮,来到 OQL 界面。在这个界面,我们可以使用类似 SQL 的语法,在 dump 中搜索数据。可以看到只创建了一个 OomService 实例,说明只有一个地方调用了 OomService 的方法。

2023010116424098723.png

然后可通过 List objects 功能搜索引用 OomService 的对象:

2023010116424149924.png

可以看到其被 main 线程引用着:

2023010116424256625.png

使用 Arthas 分析高 CPU 问题

Arthas 是阿里开源的 Java 诊断工具,相比 JDK 内置的诊断工具,要更人性化,并且功能强大,可以实现许多问题的一键定位,而且可以一键反编译类查看源码,甚至是直接进行生产代码热修复,实现在一个工具内快速定位和修复问题的一站式服务。

Arthas 官方文档: alibaba.github.io/arthas/

运行示例程序

准备如下导致CPU负载高的代码:代码中创建了2个线程的线程池,提交的任务通过 BCryptPasswordEncoder 对一个长字符串加密,这个是非常消耗CPU的。

    package com.lyyzoo.test.jvm;
    
    import java.util.concurrent.ExecutorService;
    import java.util.concurrent.Executors;
    import java.util.concurrent.Future;
    import java.util.stream.Collectors;
    import java.util.stream.IntStream;
    
    import org.apache.commons.lang3.RandomUtils;
    import org.springframework.security.crypto.bcrypt.BCryptPasswordEncoder;
    
    public class CpuService {
        private BCryptPasswordEncoder encoder = new BCryptPasswordEncoder();
        private ExecutorService executor = Executors.newFixedThreadPool(2);
    
        public void doTask() throws Exception {
            while (true) {
                randomEncode(RandomUtils.nextInt(0, 10000));
            }
        }
    
        private void randomEncode(Integer size) throws Exception {
            String payload = IntStream.rangeClosed(1, size).mapToObj(__ -> "A").collect(Collectors.joining());
            Future<String> f1 = executor.submit(() -> {
                return encoder.encode(payload);
            });
            Future<String> f2 = executor.submit(() -> {
                return encoder.encode(payload);
            });
    
            f1.get();
            f2.get();
        }
    }
    public class CpuMain {
        private static CpuService service = new CpuService();
    
        public static void main(String[] args) throws Exception {
            service.doTask();
        }
    }

启动 Arthas

首先,下载 Arthas: arthas.aliyun.com/arthas-boot…

然后把程序先运行起来,再运行 arthas:java -jar arthas-boot.jar

启动后,直接找到我们要排查的 JVM 进程,然后可以看到 Arthas 附加进程成功:

2023010116424336326.png

输入 help 命令,可以看到所有支持的命令列表。这里主要会用到 dashboard、thread、jad、watch 等命令,来定位高CPU的问题。

2023010116424441527.png

dashboard — 展示整体情况

dashboard 命令整体展示了进程所有线程、内存、GC 等情况,可以明显看到两个CPU占用很高的线程,从线程名字来看应该是线程池的线程。

2023010116424506228.png

thread — 查看高CPU的线程

接下来,查看最繁忙的线程在执行的线程栈,可以使用 thread -n 命令。这里,我们查看下最忙的 2 个线程:从线程栈可以看出,应该就是 CpuService 的 randomEncode 方法调用 BCryptPasswordEncoder 的 encode 方法导致CPU负载高的。

2023010116424606329.png

watch — 监控参数

如果想要观察方法的入参和出参,可以用 watch 命令来观察:

2023010116424699430.png

jad — 反编译

前面已经分析出CPU负载高的位置是 CpuService 的 randomEncode 了,那么通过 jad 反编译来看看源码长什么样子,方便我们进一步定位问题。

2023010116424787631.png

redefine — 重载类

如果我们想做线上调试,又不想在本地改代码,打印日志,再提交到服务器,再重启服务测试,那我们可以结合 arthas 的 jad、mc、redefine 来动态重定义类。

1、首先用 jad 把源文件下载下来

2023010116424916132.png

然后修改下源码:添加了一行输出日志

2023010116424989933.png

2、使用 mc 命令反编译源文件

反编译后会生成对应的 class 文件:

2023010116425078434.png

3、使用 redefine 重载类

2023010116425170335.png

就可以看到控制台已经在输出我们打印的日志了:

2023010116425230936.png

需要额外说明的是,由于 monitor、trace、watch 等命令是通过字节码增强技术来实现的,会在指定类的方法中插入一些切面来实现数据统计和观测,因此诊断结束要执行 shutdown 来还原类或方法字节码,然后退出 Arthas。