這個 GC 案例比較有意思，排查問題有點像偵探斷案，先分析各種可能性，再按照獲得的一個個證據，去排除各種可能性、然后定位原因，最終解決問題。

問題

某同學在微信上問我，有沒有辦法排查 YoungGC 效率低的問題？聽到這話，我也是不知從何說起，就讓他說下具體情況。 具體情況是： 有個服務在沒有 RPC 調用時，YoungGC 時間大約在 4-5ms，但是有 RPC 調用時，YoungGC 的耗時在 40ms 以上，幾乎沒有什么對象晉升，頻率 4-5 秒一次。GC 日志截圖如下。

后來他為了排查問題，把服務只留一個 RPC 調用，結果 YoungGC 更嚴重，變成 100ms 以上，幾乎沒有什么對象晉升，另外 RPC 調用耗時在 4-5ms，壓測的 QPS 也比較低，只有幾個線程在壓。GC 日志截圖如下。

另外還有一個奇葩的現象，如果測試時，只留一個調用耗時更長的 RPC 進行測試，發現 Young GC 耗時會小一點。 這里也提供下提供了下 GC 參數如下：

//GC 參數 -Xmn700m -Xms3072m -Xmx3072m -XX:SurvivorRatio=8 -XX:MetaspaceSize=384m -XX:MaxMetaspaceSize=384m -XX:+UseConcMarkSweepGC -XX:+CMSScavengeBeforeRemark -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSInitiatingOccupancyOnly -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails

可以看到，整個堆 3072M，Young Gen只有 700M，都不大。

疑惑

從上述問題來看可以判斷出：RPC 調用影響了 YoungGC 的時間。 但是你一定有很多疑惑：

• 為什么進行 RPC 調用和不進行 RPC 調用相比 YoungGC 耗時增加那么多？（Young Gen 的空間一直那么大，而且每次 GC 幾乎沒有對象晉升到 Old Gen，）

• 為什么 RPC 調用耗時長短也會影響 YoungGC 的耗時？

分析

首先，大家都知道 Young GC 是全程 stop the world 的，時間可能有多方面原因決定：

• 各個線程到達安全點的等待時間；

• 從 GC Root 掃描對象，進行標記的時間；

• 存活對象 copy 到 Survivor 以及晉升 Old Gen 到的時間；

• GC 日志的時間。

原因比較多，從表象上很難看出 YoungGC 耗時的原因，因此，我們需要收集更多的證據，來排除干擾選項，定位原因

• 對于是否線程到達安全點時間引起的原因， 我們加上顯示 Stop 時間與 Safepoint 的相關參數

//Stop時間與Safepoint的相關參數 -XX:+PrintGCApplicationStoppedTime -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1

結論也很明顯，stopping threads took 的時間都很短，可以排除此項因素。

• 對于從 GC Root 掃描對象，進行標記的時間引起的原因 我們加上顯示 GC 處理 Reference 耗時的相關參數

// 打印參數 -XX:+PrintReferenceGC

結論也很明顯，YoungGC 總耗時 110ms， 而 reference 處理耗時較長，主要是 FinalReference，耗時有 86 ms。

//YoungGC 日志 2019-01-02T17:42:53.926+0800: 409.638: [GC (Allocation Failure) 2019-01-02T17:42:53.927+0800: 409.638: [ParNew2019-01-02T17:42:53.950+0800: 409.662: [SoftReference, 0 refs, 0.0000893 secs] 2019-01-02T17:42:53.951+0800: 409.662: [WeakReference, 185 refs, 0.0000499 secs] 2019-01-02T17:42:53.951+0800: 409.662: [FinalReference, 38820 refs, 0.0865010 secs] 2019-01-02T17:42:54.037+0800: 409.749: [PhantomReference, 0 refs, 1 refs, 0.0000447 secs] 2019-01-02T17:42:54.037+0800: 409.749: [JNI Weak Reference, 0.0000220 secs]: 645120K->37540K(645120K), 0.1126527 secs] 1005305K->397726K(3074048K), 0.1128549 secs] [Times: user=0.40 sys=0.00, real=0.11 secs]

• 對于存活對象 Copy 到 Survivor 以及晉升 Old Gen 到的時間引起的原因 由于 Survivor 較小，每次 YoungGC 又幾乎沒有晉升到 Old Gen 的對象，因此很明顯，可以排除此項因素。

• 對 GC 日志的時間； 大部分 GC 日志是不耗時的，除非機器使用了大量的 swap 空間，或者其他原因導致的 iowait 較高，此項可以通過 top 或者 dstat 等命令看看 swap 使用情況以及 iowait 指標。

分析到這里，其實問題基本已經定位了，主要是 FinalReference 的處理時間比較長，導致 Young GC 時間比較長。

原理

FinalReference 是什么？

FinalReference 的具體細節，又需要一篇文章來講解。 這里簡單描述下： 對于重載了 Object 類的 finalize 方法的類實例化的對象（這里稱為 f 對象），JVM 為了能在 GC 對象時觸發 f 對象的 finalize 方法的調用，將每個 f 對象包裝生成一個對應的 FinalReference 對象，方便 GC 時進行處理。

//finalize方法 protected void finalize() throws Throwable {.... }

FinalReference 詳細解讀，可以看下你假笨大神的這篇博客JVM源碼分析之FinalReference完全解讀

FinalReference 來源何處？

FinalReference 對于沒有實現 finalize 的程序，一般是不會出現的，到底是來源何處呢？ 這里進行 JVM dump，然后通過 MAT 工具分析

很明顯，是 SocksSocketImpl 對象，我們看下 SocksSocketImpl 類實現

//SocksSocketImpl finalize 的實現 /** * Cleans up if the user forgets to close it. */ protected void finalize() throws IOException {close(); }

這里是為了防止 Socket 連接忘記關閉導致資源泄漏而進行的保底措施。

為什么FinalReference GC 處理這么耗時？

為什么 JVM GC 處理 FinalReference 這么耗時呢，通過 GC 日志，可以看出有 38820 個 reference，耗時 86ms。

2019-01-02T17:42:53.951+0800: 409.662: [FinalReference, 38820 refs, 0.0865010 secs]

對于這個問題擼過 JVM 源碼，但是一直沒有搞清楚， 其實我的另一篇博客 PhantomReference導致CMS GC耗時嚴重，也是類似，reference 個數不多，但是 GC 處理非常耗時，影響系統性能。

如何解釋問題的想象？

看到上面的 FinalReference 主要是 Socket 引起的，當時就推想到為什么會有這么多 Socket 對象需要 GC，所以問某同學難道你使用的是短連接？得到的回答是肯定的，瞬間豁然開朗。 上文提到的兩個疑惑就很容易解釋了：

• 對于“為什么進行 RPC 調用和不進行 RPC 調用相比 YoungGC 耗時增加那么多？”問題 RPC 調用使用的是短連接，每調用一次就會創建一個 Socket 對象，致使 FinalReference 對象非常多， 因此，YoungGC 耗時增加。

• 對于“為什么 RPC 調用耗時長短也會影響 YoungGC 的耗時？”問題 由于 RPC 調用耗時長的，同樣的線程數，調用的 QPS 就低，QPS 低自然創建的 Socket 對象就少，致使 FinalReference 對象少，因此，YoungGC 耗時相比就會小一些。

解決

理解了問題產生的原理，解決問題自然變得非常簡單。

• 通用方法?

加上 ParallelRefProcEnabled 參數可以使得 Reference 在 GC 的時候多線程并行處理過程，自然耗時就會降下來。

//ParallelRefProcEnabled 參數 -XX:+ParallelRefProcEnabled

• 減少 GC 的 Reference 數量?

減少 GC 的 Reference 方法比較多，不同的案例不同的處理方法，能減少 GC 的 Reference 數量就好。 這里也很簡單，RPC 調用短連接改用長鏈接，自然就能減少 GC 的 Reference 數量。 該案例就使用了這個方案，效果也很明顯，YoungGC 時間直接降低到了 14ms。

總結

本案例總結原因就是 RPC 使用短連接調用，導致 Socket 的 FinalReference 引用較多，致使 YoungGC 耗時較長。因此，通過將短連接改成長連接，減少了 Socket 對象的創建，從而減少 FinalReference，來降低 YoungGC 耗時。 在看本篇文章之前，你一定不會想到 JVM GC 處理 FinalReference 耗時這么長；你也一定不會想到短連接還有影響 GC 耗時的壞處。 排查問題的過程，很享受，不僅可以證明所學，也可以錘煉技術。

總結

以上是生活随笔為你收集整理的一次 Young GC 的优化实践的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。