歡迎光臨
每天分享高質量文章

一次 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 耗時的壞處。排查問題的過程,很享受,不僅可以證明所學,也可以錘煉技術。

赞(0)

分享創造快樂