一次 Young GC 的最佳化實踐（FinalReference 相關）

本文轉載自公眾號：滌生的部落格，閱讀時間大約需要11分鐘。滌生的文章看起來跟破案一樣，很精彩，很有啟發。

前言

部落格已經好久沒有更新了，主要原因是 18 年下半年工作比較忙，另外也沒有比較有意思的題材，所以遲遲沒有更新。此篇是 18 年底的微信上的某同學提供的一個 Young GC 問題案例，找我幫忙解決。這個 GC 案例比較有意思，雖然過去有一段時間了，但是想想覺得還是有必要寫出來，應該對大家很有幫助。排查問題有點像偵探斷案，先分析各種可能性，再按照獲得的一個個證據，去排除各種可能性、然後定位原因，最終解決問題。

問題

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

後來他為了排查問題，把服務只留一個 RPC 呼叫，結果 YoungGC 更嚴重，變成 100ms 以上，幾乎沒有什麼物件晉升，另外 RPC 呼叫耗時在 4-5ms，壓測的 QPS 也比較低，只有幾個執行緒在壓。

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

1. //GC 引數
2. -Xmn700m -Xms3072m -Xmx3072m -XX:SurvivorRatio=8
3. -XX:MetaspaceSize=384m -XX:MaxMetaspaceSize=384m -XX:+UseConcMarkSweepGC
4. -XX:+CMSScavengeBeforeRemark -XX:CMSInitiatingOccupancyFraction=80
5. -XX:+UseCMSInitiatingOccupancyOnly -XX:+PrintGC -XX:+PrintGCDateStamps
6. -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 的相關引數

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

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

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

1. // 列印引數
2. -XX:+PrintReferenceGC

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

1. //YoungGC 日誌
2. 2019-01-02T17:42:53.926+0800: 409.638: [GC (Allocation Failure)
3. 2019-01-02T17:42:53.927+0800: 409.638: [ParNew2019-01-02T17:42:53.950+0800: 409.662: [SoftReference, 0 refs, 0.0000893 secs]
4. 2019-01-02T17:42:53.951+0800: 409.662: [WeakReference, 185 refs, 0.0000499 secs]
5. 2019-01-02T17:42:53.951+0800: 409.662: [FinalReference, 38820 refs, 0.0865010 secs]
6. 2019-01-02T17:42:54.037+0800: 409.749: [PhantomReference, 0 refs, 1 refs, 0.0000447 secs]
7. 2019-01-02T17:42:54.037+0800: 409.749: [JNI Weak Reference, 0.0000220 secs]: 645120K->37540K(645120K), 0.1126527 secs]
8. 1005305K->397726K(3074048K), 0.1128549 secs]
9. [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 時進行處理。

1. //finalize方法
2. protected void finalize() throws Throwable {
3.    ....
4. }

FinalReference 詳細解讀，可以看下你假笨大神的這篇部落格JVM原始碼分析之FinalReference完全解讀

FinalReference 來源何處？

FinalReference 對於沒有實現 finalize 的程式，一般是不會出現的，到底是來源何處呢？這裡進行 JVM dump，然後透過 MAT 工具分析

很明顯，是 SocksSocketImpl 物件，我們看下 SocksSocketImpl 類實現

1. //SocksSocketImpl finalize 的實現
2. /**
3. * Cleans up if the user forgets to close it.
4. */
5. protected void finalize() throws IOException {
6.      close();
7. }

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

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

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

1. 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 的時候多執行緒並行處理過程，自然耗時就會降下來。

1. //ParallelRefProcEnabled 引數
2. -XX:+ParallelRefProcEnabled

 

• 減少 GC 的 Reference 數量 

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

總結

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