实战案例-优化系列实战收藏-解决篇

【日活百万DS App】一次线上JVM问题定位排查

2020-03-25  本文已影响0人  cmazxiaoma

前言

这篇文章最早是写于2019-08-14,在公司的confluence发布过。由于最近想标记整理压缩一些知识点碎片，于是便有了这篇文章的诞生。

项目介绍

线上排查工具介绍

线上排查使用到的命令

查看进程使用gc情况: jstat -gc 16969<pid> 5000(打印时间间隔)

类加载统计
jstat -class 16969<pid>

java进程堆栈信息打印
jstack 16969<pid>

查看pid对应的线程使用CPU情况和内存占用:
top -Hp pid

打印当前java堆中各个对象的数量,大小一页数据为50
jmap -histo pid | more -n 50

查看java堆中实例数数量前10的类
jmap -histo pid | sort -n -r -k 2 | head -10

查看java堆中容量前10的类
jmap -histo pid | sort -n -r -k 3 | head 10

查看整个JVM内存状态
jmap -heap <pid>

快照java堆信息到指定文件(会触发Full GC, 如果快照文件过大,会使目标进程stop world)
jmap -dump:format=b,file=quMall.dump 16969<pid>

显示堆中活跃对象的统计信息,比如实例数量,占用空间(会触发Full GC)
jmap -histo:live <pid>

查看进程使用的GC算法(实际上用到了javaagent技术来实现的：
jinfo -flags 23467<pid>

查看应用运行的时间
ps -p 11864<pid> -o etime

显示垃圾回收的相关信息, 同时显示最后一次或当前正在发生的垃圾回收的诱因
jstat -gccause <pid> 5000<interval>

查看GC使用情况(比如s0区使用了多少):
jstat -gcutil 6011<pid>

查看JVM内存中三代（young,old,metaspace）对象的使用和占用大小
jstat -gccapacity <pid>

查看metaspace中对象的信息及其占用量
jstat -gcmetacapacity<pid>

查看年轻代对象的信息
jstat -gcnew <pid>

查看年轻代对象的信息及其占用量
jstat -gcnewcapacity <pid>

查看old代对象的信息
jstat -gcold <pid>

查看old代对象的信息及其占用量
jstat -gcoldcapacity <pid>

查看进程是否启动AdaptiveSizePolicy策略
jinfo -flag UseAdaptiveSizePolicy 26626<pid>

查看MetaSpace默认初始化大小(默认是20.8MB)
java -XX:+PrintFlagsInitial|grep Meta

打印整个堆中对象的统计信息，按对象的total size排序
./vjmap.sh -all PID > /tmp/histo.log

推荐，打印老年代的对象统计信息，按对象的oldgen size排序，比-all快很多，暂时只支持CMS
./vjmap.sh -old PID > /tmp/histo-old.log

推荐，打印Survivor区的对象统计信息，默认age>=3
./vjmap.sh -sur PID > /tmp/histo-sur.log

推荐，打印Survivor区的对象统计信息，查看age>=4的对象
./vjmap.sh -sur:minage=4 PID > /tmp/histo-sur.log

推荐，打印Survivor区的对象统计信息，单独查看age＝4的对象
./vjmap.sh -sur:age=4 PID > /tmp/histo-sur.log

仅输出存活的对象,原理为正式统计前先执行一次full gc
./vjmap.sh -old:live PID > /tmp/histo-old－live.log

过滤对象大小，不显示过小的对象。按对象的oldgen size进行过滤，只打印OldGen占用超过1K的数据
./vjmap.sh -old:minsize=1024 PID > /tmp/histo-old.log

dump文件分析

1.快照目标进程的堆信息到执行文件jmap -dump:format=b,file=mall.dump 16969<pid>。dump文件比较大,如果从生产服务器拉到本地,会触发带宽报警。如果要执行该操作，请在电商研发团队事先@所有人。

2.使用mat工具打开堆快照文件。(mat的基本操作可以看参考文章)

Image.png

3.点开Reports->Leak Suspects 查看有可能内存泄漏的地方，
，可以体现出哪些对象被保持在内存中，以及为什么它们没有被垃圾回收。
图1可以看到WebappClassLoader占用了25,177,944字节的容量，
这是tomcat的类加载器，JDK自带的系统类加载器中占用比较多的是HashMap，这个其实比较正常。 图2可以看到JDBC4Connection的实例有539个，占用的空间是22,302,560字节，这个是比较可疑。

Image [1].png Image [2].png

4.点开Actions->Histogram，模拟搜索JDBC。发现关于JDBC相关的实例数还挺多的。右键点击com.mysql.jdbc.JDBC4Connection，选择with outgoing references 查看JDBC4Connection实例具体的依赖关系。

Image [4].png Image [5].png Image [6].png

5.选中一个JDBC4Connection实例，右键选择Merge Shortest Paths to GC roots -> with all references查看JDBC4Connection到GC roots的路径。

6.可见JDBC4Connection被2个对象引用，一个是BasicResourcePool中的formerResources(曾经在连接池里呆过的对象)变量，一个是MySQL JDBC Driver的ConnectionPhantomReference

Image [6].png

NonRegisteringDriver.java

Image [7].png

这个虚引用是在JDBC Driver在构造connection时用来track这个connection的，在被GC回收前做一些clean up（释放资源）的事情，所以每个connection被构造出来后，都会被track，这是Driver为了防止有资源随着连接回收而未释放的手段。


public class AbandonedConnectionCleanupThread extends Thread {
    private static boolean running = true;
    private static Thread threadRef = null;

    public AbandonedConnectionCleanupThread() {
        super("Abandoned connection cleanup thread");
    }

    public void run() {
        threadRef = this;
        while (running) {
            try {
                Reference<? extends ConnectionImpl> ref = NonRegisteringDriver.refQueue.remove(100);
                if (ref != null) {
                    try {
                        ((ConnectionPhantomReference) ref).cleanup();
                    } finally {
                        NonRegisteringDriver.connectionPhantomRefs.remove(ref);
                    }
                }

            } catch (Exception ex) {
                // no where to really log this if we're static
            }
        }
    }

    public static void shutdown() throws InterruptedException {
        running = false;
        if (threadRef != null) {
            threadRef.interrupt();
            threadRef.join();
            threadRef = null;
        }
    }

}

被PhantomReference引用的对象在被GC时,
JVM会将PhantomReference对象扔到refqueue。然后会通过
AbandonedConnectionCleanupThread这个线程从NonRegisteringDriver.refQueue中拿到ConnectionPhantomReference，然后执行cleanup方法，最后删除connectionPhantomRefs这个ConcurrentHashMap中的ConnectionPhantomReference对象，完成connection相关资源的回收。

但是我们排查的结果是ConnectionPhantomReference并没有得到清理。经过查阅一些资料，得出以下结论:

似乎问题是CompressionInputStream'有对同一ConnectionImpl的引用，ConnectionPhantomReference正在等待在ReferenceQueue上排队，说它有资格进行垃圾回收。ConnectionPhantomReference通过它引用的com.mysql.jdbc.NetworkResources对象对CompressionInputStream有一个强引用。ConnectionPhantomReference由NonRegisteringDriver中的静态ConcurrentHashMap强烈保存。结果是ConnectionPhantomReference有效地引用了它要等待GC的JDBC4Connection对象; 并使JDBC4Connection实例保持活动状态，因此不符合垃圾回收的条件。

Image [8].png

所以在我们程序中要定时去清除ConnectionPhantomReference引用。在quMall项目中一台服务器中Full GC清除7110个PhantomReference引用，耗时竟然达到0.6s。但是通过程序定时删除这些引用,下一次Full GC清除这些引用耗时可以忽略不计。

/**
 * @author xiaoma
 * @version V1.0
 * @Description: 解决PhantomReference引用过多,造成内存泄漏
 * PhantomReference, 7110 refs, 587 refs, 0.6012897 secs
 * @date 2019/8/12 15:12
 */
@Service
public class MysqlConnectionPhantomRefCleaner implements InitializingBean {

    private Field declaredField;
    private ConcurrentHashMap referenceMap;

    @Override
    public void afterPropertiesSet() throws Exception {
        try {
            declaredField = NonRegisteringDriver.class.getDeclaredField("connectionPhantomRefs");
            declaredField.setAccessible(true);
            referenceMap = (ConcurrentHashMap<?, ?>) declaredField.get(null);
        } catch (Exception ex) {
            LogService.info(MessageFormat.format(
                    "清除PhantomReference计划, 初始化失败:{0}",
                    ex.getMessage()
            ));
        }
    }

    /**
     * 每秒10s清理一次
     */
    @PostConstruct
    public void clear() {
        ScheduledExecutorService scheduledExecutorService = Executors.newScheduledThreadPool(1);
        LogService.info("清除PhantomReference计划, 初始化成功");

        synchronized (MysqlConnectionPhantomRefCleaner.class) {
            scheduledExecutorService.scheduleAtFixedRate(new Runnable() {
                @Override
                public void run() {
                    if (!referenceMap.isEmpty()) {
                        int size = referenceMap.size();
                        LogService.info(MessageFormat.format(
                                "清除PhantomReference计划, current Mysql ConnectionPhantomReference map size:{0} start to clear",
                                size

                        ));
                        referenceMap.clear();
                    }
                }
            }, 1, 10, TimeUnit.SECONDS);
        }
    }

}
Image [9].png

7.再来讲讲formerResources引用，我列出formerResources
相关代码。

private void removeResource(Object resc, boolean synchronous){
    ...
    unused.remove(resc);
    destroyResource(resc, synchronous, checked_out);

    addToFormerResources( resc );

    asyncFireResourceRemoved( resc, false, managed.size(), unused.size(), excluded.size() );
    ...
}

private void cullExpired(){
    ...
    if ( shouldExpire( resc ) )
    {
        if ( logger.isLoggable( MLevel.FINER ) )
            logger.log( MLevel.FINER, "Removing expired resource: " + resc + " [" + this + "]");

        target_pool_size = Math.max( min, target_pool_size - 1 ); //expiring a resource resources the target size to match

        removeResource( resc );
    }
    ...
}

public Object checkoutResource( long timeout ){

    Object resc = prelimCheckoutResource( timeout );

...
}

private synchronized Object prelimCheckoutResource( long timeout ){
    ...
    Object  resc = unused.get(0);
    ...
    else if ( shouldExpire( resc ) ){
      removeResource( resc );
      ensureMinResources();
      return prelimCheckoutResource( timeout );
    }
}

cullExpired这个方法是c3p0的一个定时器里执行的方法，用来检查过期连接的。c3p0会定时对idle连接进行连接池过期检查。若空闲时间超过MaxIdleTime，则会remove，会加入到formerResources中。如果最后剩下的idle连接数超过或者小于minIdle的连接数，也会相应的进行缩减或者扩容，直到minIdle个连接数。

idleConnectionTest是维持连接池的idle连接和MySQL之间的心跳，防止MySQL Server端踢掉应用的连接，而前面提到的连接池过期检查则是c3p0对连接归还后是否长时间没被再次借出为依据来判断连接是否过期。

如果配置了maxIdleTime, 处于keep alived的连接会被认为是过期连接。连接池将丢弃这些连接，并创建新连接。因此,NonRegisteringDriver将慢慢地保留越来越多的JDBC4Connection对象，并且您将慢慢地发生内存泄漏。 这里也会造成频繁的Young GC。

checkoutResource是每次获取连接的时候，会对连接进行过期检查的校验。如果连接空闲时间超过MaxIdleTime,该连接会标志已经过期，
调用removeResource，将连接加入到formerResources中。配置了MaxIdeTime参数，checkout操作会加快过期连接的失效和创建新连接的速度，导致formerResources里退休的连接变多，最终加快了老年代的增长和内存泄漏。

正确的姿势是去掉maxIdleTime配置，
配置了idleConnectionTestPeriod这个参数即可。

类似的问题还会存在JedisPoolConfig中，这些都可以归结成持久化对象在JVM中的存活生命周期问题。
连接池对象，本地缓存对象都是，这些对象存活时间久，处于JVM的老生代中，应用希望尽可能的重用它们，但若结合具体场景的配置或使用不合理，导致这些对象并未最大化被重用，比如上面提到的过期检查导致不断有新的对象被创建出来，因为是持久化对象，很容易就进入到了老生代，霸占了资源。

Image [10].png

上图是JedisPoolConfig默认配置，每30秒进行一次扫描，如果发现有空闲时间超过60s连接，执行清除操作。如果当前连接少于minIdle个,则会再创建新的。而清除掉的连接若未及时的被YGC掉，会进入到老年代。

Image [11].png

我们只需配置minEvictableIdleTimeMills=-1，softMinEvictableIdleTimeMillis=60000就可以上述的问题。这样就不会对minIdle的连接进行清理，只有当连接数超过minIdle后,才进行清理工作。

JVM基础参数

-XX:ParallelGCThreads=8
JVM在进行并行GC的时候,用于GC的线程数，一般是机器的核数。

-XX:+UseConcMarkSweepGC
打开此开关参数后，使用ParNew+CMS+Serial Old收集器组合进行垃圾收集。Serial Old作为CMS收集器出现Concurrent Mode Failure的备用垃圾收集器。

-XX:+UseParallelGC
打开此开关参数后，使用Parallel Scavenge+Serial Old收集器组合进行垃圾收集。

-XX:+UseParallelOldGC
打开此开关参数后，使用Parallel Scavenge+Parallel Old收集器组合进行垃圾收集。

JDK1.8 默认使用Parallel Scavenge年轻代回收器和Parallel Old老年代回收器, 默认打开AdaptiveSizePolicy策略。CMS默认关闭AdaptiveSizePolicy策略。在quMall项目中,没有关闭AdaptiveSizePolicy策略，造成S0,S1区只有8MB，从而导致频繁Young GC。所以要手动设置使Eden:S0:S1 = 8 : 1 : 1

-XX:SurvivorRatio=8
-XX:-UseAdaptiveSizePolicy

AdaptiveSizePolicy为了达到三个预期目标，涉及以下操作：

引用R大说过的话：
HotSpot VM里，ParallelScavenge系的GC（UseParallelGC,UseParallelOldGC）默认行为是SurvivorRatio如果不显式设置就没啥用。显式设置到跟默认值一样的值则会有效果。因为ParallelScavenge系的GC最初设计就是默认打开AdaptiveSizePolicy的，它会自动、自适应的调整各种参数

在这里说下默认的ParallelScavenge 和 ParallelOld垃圾回收器:

对于重载了 Object 类的 finalize 方法的类实例化的对象（这里称为 f 对象)，JVM 为了能在GC 对象时触发f对象的finalize 方法的调用，将每个f对象包装生成一个对应的FinalReference 对象，方便 GC 时进行处理。

SocksSocketImpl中重载了finalize方法，防止Socket 连接忘记关闭导致资源泄漏而进行的保底措施。

Image [12].png

对于RPC调用短连接场景，每调用一次就会创建一个Socket 对象。致使 FinalReference 对象非常多, 因此YoungGC 耗时增加。
下面参数, 可以在 GC 的时候多线程并行处理Reference，降低GC时长。
-XX:+ParallelRefProcEnabled

开启压缩对象指针(默认开启)，启用CompressOops后，会压缩的对象：
• 每个Class的属性指针（静态成员变量）
• 每个对象的属性指针
• 普通对象数组的每个元素指针。
-XX:+UseCompressedOops

在Metaspace中开辟出一块类指针压缩空间(Compressed Class Space)，默认是1G(默认开启)。对象中指向类元数据的指针会被压缩成32位。

-XX:+UseCompressedClassPointers
-XX:CompressedClassSpaceSize=1G

使用CMS时，打开对年老代的压缩。可能会影响性能，但是可以消除碎片。
-XX:+UseCMSCompactAtFullCollection

使用CMS，设置多少次FullGc后，对年老代进行压缩。
由于CMS不对内存空间进行压缩、整理、所以运行一段时间以后会产生“碎片”，使得运行效率降低。此值设置运行多少次GC以后对内存空间进行压缩、整理。

-XX:CMSFullGCsBeforeCompaction=0

这两个设置一般配合使用,一般用于『降低CMS GC频率或者增加频率、减少GC时长』的需求

-XX:CMSInitiatingOccupancyFraction=70 是指设定CMS在对内存占用率达到70%的时候开始GC(因为CMS会有浮动垃圾,所以一般都较早启动GC);

-XX:+UseCMSInitiatingOccupancyOnly 只是用设定的回收阈值(上面指定的70%),如果不指定,JVM仅在第一次使用设定值,后续则自动调整。

CMS整个过程分为4步：

在CMS GC前启动一次ygc，目的在于减少old gen对ygc gen的引用，降低remark时的开销, 一般CMS的GC耗时80%都在remark阶段。
-XX:+CMSScavengeBeforeRemark

在进行GC的前后打印出堆的信息
-XX:+PrintHeapAtGC

输出GC的详细日志
-XX:+PrintGCDetails

输出GC的时间戳（以基准时间的形式）
-XX:+PrintGCDateStamps

打印GC时各种引用的处理时间。
-XX:+PrintReferenceGC

输出GC日志
-XX:+PrintGC

打开了就知道是多大的新生代对象晋升到老生代失败从而引发Full GC时的。
-XX:+PrintPromotionFailure

输出显示在survivor空间里面有效的对象的岁数情况。
-XX:+PrintTenuringDistribution

打印产生GC的原因，比如AllocationFailure什么的，在JDK8已默认打开，JDK7要显式打开一下。
-XX:+PrintGCCause

GC日志存放的位置。

-Xloggc:logs/quMall_gc.log"

如果达到初始化值就会触发垃圾收集进行类型卸载，同时GC会对该值进行调整：如果释放了大量的空间，就适当降低该值；如果释放了很少的空间，那么在不超过MaxMetaspaceSize时，适当提高该值。默认值是20.8MB。如果不手动指定元空间的大小，会因为元空间的扩容机制，造成频繁的Full GC。

-XX:MetaspaceSize=256m 
-XX:MaxMetaspaceSize=256m

默认(MinHeapFreeRatio参数可以调整)空余堆内存小于40%时，JVM就会增大堆直到-Xmx的最大限制。
默认(MaxHeapFreeRatio参数可以调整)空余堆内存大于70%时，JVM会减少堆直到 -Xms的最小限制。
注意:java应用的jvm参数Xms与Xmx保持一致，避免因所使用的Java堆内存不够导致频繁full gc以及full gc中因动态调节Java堆大小而耗费延长其周期。

-XX:MinHeapFreeRatio=40
-XX:MaxHeapFreeRatio=70
-Xms3072m 
-Xmx3072m

如果没有配置-XX:+DisableExplicitGC，即没有屏蔽System.gc()触发FullGC，那么可以通过排查GC日志中有System字样判断是否System.gc()触发。
注意：如果应用中有用到Netty并且配置了该参数会内存溢出。
Netty中的DirectByteBuffer分配空间过程中发现直接内存不足时会显式调用System.gc()，以期通过Full GC来强迫已经无用的DirectByteBuffer对象释放掉它们关联的native memory。

-XX:+DisableExplicitGC

GC日志分析

之前看到电商模块中的一台服务器实例频繁Full GC和YGC，感觉很不正常，以下是排查定位问题的步骤。

Image [14].png

1.先定位整个堆中哪些对象的实例数和占用空间比较多。话外音：如果垃圾回收器使用的是CMS和ParallelGC，可以使用vjmap快速定位年老代和Survivor区的对象统计信息，减少卡顿时间。
使用jmap -histo:live <pid>命令，可以看到跟JDBC相关类的实例数和占用空间比较多。为了进一步验证猜想,可以dump文件导入到mat工具进行分析(上面已经验证了JDBC存在内存泄漏)。

Image [15].png

2.使用jstat -gc 16969<pid> 5000<interval>命令查看gc情况，发现S0和S1区只有7-8MB。接着使用jstat -gcutil 6011<pid>查看堆中各区域使用情况，发现S0区占比很高。

Image [16].png Image [17].png

因为使用的是Parallel Scavenge、Parallel Old垃圾回收器，会启动AdaptiveSizePolicy策略。当这个参数打开之后，就不需要手工指定新生代的大小（-Xmn）、Eden与Survivor区的比例（-XX:SurvivorRatio）、晋升老年代对象大小门槛（-XX:PretenureSizeThreshold）等细节参数了，虚拟机会根据当前系统的运行情况收集性能监控信息，动态调整这些参数以提供最合适的停顿时间或最大的吞吐量，这种调节方式称为GC自适应的调节策略（GC Ergonomics）。

所以我们要禁用这个参数且将Eden:S0:S1设置为8:1:1

-XX:SurvivorRatio=8
-XX:-UseAdaptiveSizePolicy

设置完这个参数后，再查看GC使用情况后，发现S0和S1区容量变大，S0区占用比也急剧减少，从而YGC减少。

Image [18].png Image [19].png

3.查看GC日志，发现造成频繁Full GC的原因是Metadata GC Threshold。这由于没有设置Metaspace参数，导致初始化大小为20.8MB的元空间不够用，频繁扩容导致的Full GC。

-XX:MetaspaceSize=256m 
-XX:MaxMetaspaceSize=256m
Image [20].png
  1. 如果使用jmap -histo:live <pid>和jmap -dump:format=b,file=quMall.dump 16969<pid>会造成Full GC。
jmap命令导致的Full GC.jpg

5.可以看到Full GC时清除7100个PhantomReference引用耗时长达0.6s。根据上面的分析，我们应该定时清除PhantomReference引用。同时设置并行处理引用。优化后的Full GC清除PhantomReference引用耗时0.0000805s。

-XX:+ParallelRefProcEnabled
Image [21].png

6.另外需要注意的是-Xms和 -Xmx应该设置成一样大，避免在每次GC 后调整堆的大小，从而造成频繁Full GC。

之前没有优化时，近2天GC的情况。

优化前.jpg

优化后，近2天GC的情况。

优化后.jpg

后续观察JVM状况

优化后.png 优化前.png

参考文章

尾言

感谢各位大佬观看。
如果您对这篇文章有什么意见或者错误需要改进的地方,欢迎与我讨论。

上一篇下一篇

猜你喜欢

热点阅读