背景

線上應用頻繁出現(xiàn)超時告警（超時時間 1 s）： getUiToken 接口異常狀態(tài)碼“-1”出現(xiàn)4037次(失敗描述:業(yè)務請求異常)，超過閾值50，協(xié)議：http，為服務端接口。當前失敗率為0%，當前平均響應時間為150ms，TP50為2ms,TP90為896ms，TP99為1024ms,TP999為1152ms,MAX為1280ms。

環(huán)境信息

?服務器配置為，Linux 4c8g 標配機器

?JVM 參數(shù)配置：

-server -Djava.library.path=/usr/local/lib -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/export/log -Djava.awt.headless=true -Dsun.net.client.defaultConnectTimeout=60000 -Dsun.net.client.defaultReadTimeout=60000 -Djmagick.systemclassloader=no -Dnetworkaddress.cache.ttl=300 -Dsun.net.inetaddr.ttl=300 -Xms5G -Xmx5G -XX:+UseG1GC -XX:G1HeapRegionSize=4m -Xloggc:/export/log/$APP_NAME/gc_detail.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10m -XX:MaxTenuringThreshold=15 -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC

?接口流量情況：

問題排查

分析代碼實現(xiàn)，getUiToken 只是簡單的內(nèi)存數(shù)據(jù)獲取并返回，沒有其他復雜操作，不存在有耗時操作

接著借助 SGM 監(jiān)控平臺分析下接口耗時情況，發(fā)現(xiàn)方法執(zhí)行的耗時都處在等待中，為什么會有這多長的等待時間呢？

業(yè)務代碼很簡單，只是內(nèi)存級別的獲取，序列化和反序列化也不可能耗時這么久， 難道是 GC 的原因 ？ 因為 JVM 之前就配置了 -Xloggc 日志輸出，所以先分析下 GC 日志情況，看看 GC 是否存在異常情況（工具 gcViewer）

果然，光看吞吐量 99.3% 和 full gc 次數(shù) 0，感覺性能好像還不錯的，但 4227 次 young gc （平均 20 多秒一次） 和 max 1.25 秒的耗時，就有點離譜，分析 GC 日志詳情

隨機搜查了一個 GC 耗時在 1s 以上的日志，發(fā)現(xiàn) 1.02 s 的 gc 有 977.3 ms 是在處理 Ref Proc，為什么這個耗時會這么長 ？

ref-proc 是對各種軟弱虛引用等的處理，處理 soft、weak、phantom、final、JNI 等等引用的時間

具體是那種引用類型的耗時長，可以通過增加 JVM 參數(shù) -XX:+PrintReferenceGC 打印引用GC類型 ，重新上線一段時間后觀察GC日志

發(fā)現(xiàn)耗時基本都在 PhantomReference 類型的對象上，為什么會有這么多這個對象？

PhantomReference 是什么？ 1、虛引用也稱為“幽靈引用”，它是最弱的一種引用關系。 2、如果一個對象僅持有虛引用，那么它就和沒有任何引用一樣，在任何時候都可能被垃圾回收器回收。 3、為一個對象設置虛引用關聯(lián)的唯一目的只是為了能在這個對象被收集器回收時收到一個系統(tǒng)通知。 4、當垃圾回收器準備回收一個對象時，如果發(fā)現(xiàn)它還有虛引用，就會在垃圾回收后，將這個虛引用加入引用隊列，在其關聯(lián)的虛引用出隊前，不會徹底銷毀該對象。所以可以通過檢查引用隊列中是否有相應的虛引用來判斷對象是否已經(jīng)被回收了。

為了搞清楚 PhantomReference 具體都是哪些對象，我們需要 dump 堆文件查看對象的分布（內(nèi)存分析工具 MAT），dump 時最好將流量摘除后操作，以免影響線上。查看直方圖中的對象發(fā)現(xiàn)有 4340 個虛引用對象，和GC日志中的數(shù)量基本對的上。

那為什么會有這么多 ConnectionPhantomReference 對象呢 ？ 這個東西有什么用呢 ？ 源碼如下 （mysql-connector-java 版本 5.1.44）

// 相關的核心邏輯
public class NonRegisteringDriver implements java.sql.Driver {
    protected static final ConcurrentHashMap connectionPhantomRefs = new ConcurrentHashMap();
    protected static final ReferenceQueue refQueue = new ReferenceQueue(); 

    protected static void trackConnection(Connection newConn) {
        ConnectionPhantomReference phantomRef = new ConnectionPhantomReference((ConnectionImpl) newConn, refQueue);
        connectionPhantomRefs.put(phantomRef, phantomRef);
    }
}

public class ConnectionImpl extends ConnectionPropertiesImpl implements MySQLConnection {
  public ConnectionImpl(String hostToConnectTo, int portToConnectTo, Properties info, String databaseToConnectTo, String url) throws SQLException {
    ...
    NonRegisteringDriver.trackConnection(this);
  }
}

通過代碼發(fā)現(xiàn)，每次新建數(shù)據(jù)庫連接 Connection 時都會向 connectionPhantomRefs 存放一個對象，那么已經(jīng)使用 druid （版本：1.0.15）線程池為什么還會生成這么多新鏈接 ？ 接著查看項目中的數(shù)據(jù)庫配置，發(fā)現(xiàn)數(shù)據(jù)源使用的是默認配置

# 線程池使用的默認配置
spring:
  datasource:
    url: jdbc:mysql://xxxxxxxxx?useUnicode=true&characterEncoding=utf8&allowMultiQueries=true&serverTimezone=GMT%2B8
    username: xxxx
    password: xxxx
    driver-class-name: com.mysql.jdbc.Driver
    type: com.alibaba.druid.pool.DruidDataSource

默認配置中，線程池中的連接存活時間為 30 分鐘，最小閑置線程數(shù)為 0，因此雖使用了線程池也還是會不斷的創(chuàng)建新的鏈接，并增加到 connectionPhantomRefs 集合中，累計一定量之后就會影響 ref-proc 耗時。

如何解決 ？

既然因為它累計的量大導致 gc 時長變高，那么我們分析下 connectionPhantomRefs 的作用到底是什么 ？

跟進 connectionPhantomRefs 引用處理對象，發(fā)現(xiàn) connectionPhantomRefs 中的元素都是被 AbandonedConnectionCleanupThread 處理的

/**
 * This class implements a thread that is responsible for closing abandoned MySQL connections,
 * i.e., connections that are not explicitly closed. 
 * There is only one instance of this class and there is a single thread to do this task. 
 * This thread's executor is statically referenced in this same class.
 *
 * 該類實現(xiàn)了一個負責關閉被遺棄的MySQL連接的線程，即未顯式關閉的連接。該類的實例只有一個，并且由單個線程執(zhí)行此任務。該線程的執(zhí)行器在此類中以靜態(tài)方式引用。
 */
public class AbandonedConnectionCleanupThread implements Runnable {
    private static final ExecutorService cleanupThreadExcecutorService;
    static Thread threadRef = null;

    static {
        cleanupThreadExcecutorService = Executors.newSingleThreadExecutor(new ThreadFactory() {
            public Thread newThread(Runnable r) {
                Thread t = new Thread(r, "Abandoned connection cleanup thread");
                t.setDaemon(true);
                t.setContextClassLoader(AbandonedConnectionCleanupThread.class.getClassLoader());
                return threadRef = t;
            }
        });
        cleanupThreadExcecutorService.execute(new AbandonedConnectionCleanupThread());
    }

    public void run() {
        for (;;) {
            try {
                checkContextClassLoaders();
                Reference ref = NonRegisteringDriver.refQueue.remove(5000);
                if (ref != null) {
                    try {
                        ((ConnectionPhantomReference) ref).cleanup();
                    } finally {
                        NonRegisteringDriver.connectionPhantomRefs.remove(ref);
                    }
                }
            } catch (InterruptedException e) {
                threadRef = null;
                return;
            } catch (Exception ex) {
                // Nowhere to really log this.
            }
        }
    }
}

根據(jù) com.mysql.jdbc.AbandonedConnectionCleanupThread 類注釋信息，發(fā)現(xiàn)該類是 mysql 連接的兜底處理邏輯，負責關閉被遺棄的MySQL連接，主要有兩種情況

1. 未顯式關閉的連接（代碼遺漏）

2. 異常未處理的連接（程序崩潰/未捕獲異常/網(wǎng)絡或事務超時導致的連接失效）

解決方案

1. 優(yōu)化 druid 連接池連接數(shù)配置 （按實際流量情況評估），增加連接存活時長到 59 分鐘（MySql wait_timeout 默認為 3600 秒），最大限度減少新連接生成

spring:
  datasource:
    url: jdbc:mysql://xxxxxxxxx?useUnicode=true&characterEncoding=utf8&allowMultiQueries=true&serverTimezone=GMT%2B8
    username: xxxx
    password: xxxx
    driver-class-name: com.mysql.jdbc.Driver
    type: com.alibaba.druid.pool.DruidDataSource
    druid:
      # 增加線程數(shù)
      minIdle: 4
      maxActive: 10
      initialSize: 4
      # 啟動檢測線程回收
      testWhileIdle: true
      testOnBorrow: false
      testOnReturn: false
      validationQuery: select 1
      timeBetweenEvictionRunsMillis: 60000
      minEvictableIdleTimeMillis: 3540000

2. 開啟 ref-proc 并行處理：-XX:+ParallelRefProcEnabled ， G1 官網(wǎng)建議

Reference Object Processing Takes Too Long Information about the time taken for processing of Reference Objects is shown in the Ref Proc and Ref Enq phases. During the Ref Proc phase, G1 updates the referents of Reference Objects according to the requirements of their particular type. In Ref Enq, G1 enqueues Reference Objects into their respective reference queue if their referents were found dead. If these phases take too long, then consider enabling parallelization of these phases by using the option -XX:+ParallelRefProcEnabled.

3. 由于 connectionPhantomRefs 只是作為異常情況出現(xiàn)的兜底處理，我們項目中使用的線程池都會自動處理資源釋放的情況，不存在手動操作的情況，是不是可以定時清理這部分的內(nèi)容或者不使用，目前使用最多的兩種方式是

?定時任務：清理虛引用列表數(shù)據(jù)

@Component
public class CleanPhantomRefsSchedule {

    private static final ScheduledExecutorService CLEANER_EXECUTOR = Executors.newSingleThreadScheduledExecutor(r -> {
        Thread t = new Thread(r, "mysql-phantom-ref-cleaner");
        t.setDaemon(true);
        return t;
    });

    @PostConstruct
    public void doTask() {
        log.info("CleanPhantomRefsSchedule#doTask start");
        try {
            Field field = NonRegisteringDriver.class.getDeclaredField("connectionPhantomRefs");
            field.setAccessible(true);
            // 定時輪訓
            CLEANER_EXECUTOR.scheduleAtFixedRate(() -> {
                try {
                    Map connectionPhantomRefs = (Map) field.get(null);
                    // 這里我設置的稍微大一些，對 gc 沒太大影響時不進行干預
                   if (connectionPhantomRefs != null && connectionPhantomRefs.size() > 500) {
                        connectionPhantomRefs.clear();
                        log.info("Cleared MySQL phantom references (count={})", connectionPhantomRefs.size());
                    }
                } catch (Exception e) {
                    log.error("connectionPhantomRefs clear error!", e);
                }
            }, 1, 1, TimeUnit.HOURS);
        } catch (NoSuchFieldException e) {
            throw new IllegalStateException("Failed to initialize MySQL phantom refs field", e);
        }
    }

    @PreDestroy
    void shutdown() {
        CLEANER_EXECUTOR.shutdownNow();
    }
}

?升級 mysql-connector-java 版本（8.0 以上），可以通過參數(shù) ??-Dcom.mysql.cj.disableAbandonedConnectionCleanup=true?? 禁用虛引用生成

 private static booleanabandonedConnectionCleanupDisabled=Boolean.getBoolean("com.mysql.cj.disableAbandonedConnectionCleanup");

 protected static void trackConnection(MysqlConnection conn, NetworkResources io) {
    if(!abandonedConnectionCleanupDisabled){
···
ConnectionFinalizerPhantomReferencereference=newConnectionFinalizerPhantomReference(conn,io,referenceQueue);
connectionFinalizerPhantomRefs.add(reference);
···
}
}

我采用的是定時任務這種方式，因為項目升級 mysql-connector-java 版本會存在兼容性問題，其次是在虛引用量比較小的情況我希望這種兜底策略依舊可以生效，所以定時任務中只有在 connectionPhantomRefs.size() > 500 時才會干預清理，而不是直接杜絕使用

驗證優(yōu)化結果

代碼及配置調整完成后再次上線，等待一天后，繼續(xù)分析 GC日志和堆轉儲文件

結論：上線后近 12 小時數(shù)據(jù)，GC 時間最大停頓時間由原先 1.25 降低至 0.1 秒，young gc 頻率由原先的 20 秒一次優(yōu)化到 6 分鐘一次，PhantomReference 引用耗時縮減到 0.0001966 s， 持續(xù)觀察幾天，線上服務無超時告警且系統(tǒng)響應正常，優(yōu)化符合預期結果。

審核編輯 黃宇