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

問(wèn)題

某同學(xué)在微信上問(wèn)我，有沒(méi)有辦法排查 YoungGC 效率低的問(wèn)題？聽(tīng)到這話，我也是不知從何說(shuō)起，就讓他說(shuō)下具體情況。 具體情況是： 有個(gè)服務(wù)在沒(méi)有 RPC 調(diào)用時(shí)，YoungGC 時(shí)間大約在 4-5ms，但是有 RPC 調(diào)用時(shí)，YoungGC 的耗時(shí)在 40ms 以上，幾乎沒(méi)有什么對(duì)象晉升，頻率 4-5 秒一次。GC 日志截圖如下。

后來(lái)他為了排查問(wèn)題，把服務(wù)只留一個(gè) RPC 調(diào)用，結(jié)果 YoungGC 更嚴(yán)重，變成 100ms 以上，幾乎沒(méi)有什么對(duì)象晉升，另外 RPC 調(diào)用耗時(shí)在 4-5ms，壓測(cè)的 QPS 也比較低，只有幾個(gè)線程在壓。GC 日志截圖如下。

另外還有一個(gè)奇葩的現(xiàn)象，如果測(cè)試時(shí)，只留一個(gè)調(diào)用耗時(shí)更長(zhǎng)的 RPC 進(jìn)行測(cè)試，發(fā)現(xiàn) Young GC 耗時(shí)會(huì)小一點(diǎn)。 這里也提供下提供了下 GC 參數(shù)如下：

//GC 參數(shù) -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

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

疑惑

從上述問(wèn)題來(lái)看可以判斷出：RPC 調(diào)用影響了 YoungGC 的時(shí)間。 但是你一定有很多疑惑：

• 為什么進(jìn)行 RPC 調(diào)用和不進(jìn)行 RPC 調(diào)用相比 YoungGC 耗時(shí)增加那么多？（Young Gen 的空間一直那么大，而且每次 GC 幾乎沒(méi)有對(duì)象晉升到 Old Gen，）

• 為什么 RPC 調(diào)用耗時(shí)長(zhǎng)短也會(huì)影響 YoungGC 的耗時(shí)？

分析

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

• 各個(gè)線程到達(dá)安全點(diǎn)的等待時(shí)間；

• 從 GC Root 掃描對(duì)象，進(jìn)行標(biāo)記的時(shí)間；

• 存活對(duì)象 copy 到 Survivor 以及晉升 Old Gen 到的時(shí)間；

• GC 日志的時(shí)間。

原因比較多，從表象上很難看出 YoungGC 耗時(shí)的原因，因此，我們需要收集更多的證據(jù)，來(lái)排除干擾選項(xiàng)，定位原因

• 對(duì)于是否線程到達(dá)安全點(diǎn)時(shí)間引起的原因， 我們加上顯示 Stop 時(shí)間與 Safepoint 的相關(guān)參數(shù)

//Stop時(shí)間與Safepoint的相關(guān)參數(shù) -XX:+PrintGCApplicationStoppedTime -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1

結(jié)論也很明顯，stopping threads took 的時(shí)間都很短，可以排除此項(xiàng)因素。

• 對(duì)于從 GC Root 掃描對(duì)象，進(jìn)行標(biāo)記的時(shí)間引起的原因 我們加上顯示 GC 處理 Reference 耗時(shí)的相關(guān)參數(shù)

// 打印參數(shù) -XX:+PrintReferenceGC

結(jié)論也很明顯，YoungGC 總耗時(shí) 110ms， 而 reference 處理耗時(shí)較長(zhǎng)，主要是 FinalReference，耗時(shí)有 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]

• 對(duì)于存活對(duì)象 Copy 到 Survivor 以及晉升 Old Gen 到的時(shí)間引起的原因 由于 Survivor 較小，每次 YoungGC 又幾乎沒(méi)有晉升到 Old Gen 的對(duì)象，因此很明顯，可以排除此項(xiàng)因素。

• 對(duì) GC 日志的時(shí)間； 大部分 GC 日志是不耗時(shí)的，除非機(jī)器使用了大量的 swap 空間，或者其他原因?qū)е碌?iowait 較高，此項(xiàng)可以通過(guò) top 或者 dstat 等命令看看 swap 使用情況以及 iowait 指標(biāo)。

分析到這里，其實(shí)問(wèn)題基本已經(jīng)定位了，主要是 FinalReference 的處理時(shí)間比較長(zhǎng)，導(dǎo)致 Young GC 時(shí)間比較長(zhǎng)。

原理

FinalReference 是什么？

FinalReference 的具體細(xì)節(jié)，又需要一篇文章來(lái)講解。 這里簡(jiǎn)單描述下： 對(duì)于重載了 Object 類的 finalize 方法的類實(shí)例化的對(duì)象（這里稱為 f 對(duì)象），JVM 為了能在 GC 對(duì)象時(shí)觸發(fā) f 對(duì)象的 finalize 方法的調(diào)用，將每個(gè) f 對(duì)象包裝生成一個(gè)對(duì)應(yīng)的 FinalReference 對(duì)象，方便 GC 時(shí)進(jìn)行處理。

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

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

FinalReference 來(lái)源何處？

FinalReference 對(duì)于沒(méi)有實(shí)現(xiàn) finalize 的程序，一般是不會(huì)出現(xiàn)的，到底是來(lái)源何處呢？ 這里進(jìn)行 JVM dump，然后通過(guò) MAT 工具分析

很明顯，是 SocksSocketImpl 對(duì)象，我們看下 SocksSocketImpl 類實(shí)現(xiàn)

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

這里是為了防止 Socket 連接忘記關(guān)閉導(dǎo)致資源泄漏而進(jìn)行的保底措施。

為什么FinalReference GC 處理這么耗時(shí)？

為什么 JVM GC 處理 FinalReference 這么耗時(shí)呢，通過(guò) GC 日志，可以看出有 38820 個(gè) reference，耗時(shí) 86ms。

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

對(duì)于這個(gè)問(wèn)題擼過(guò) JVM 源碼，但是一直沒(méi)有搞清楚， 其實(shí)我的另一篇博客 PhantomReference導(dǎo)致CMS GC耗時(shí)嚴(yán)重，也是類似，reference 個(gè)數(shù)不多，但是 GC 處理非常耗時(shí)，影響系統(tǒng)性能。

如何解釋問(wèn)題的想象？

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

• 對(duì)于“為什么進(jìn)行 RPC 調(diào)用和不進(jìn)行 RPC 調(diào)用相比 YoungGC 耗時(shí)增加那么多？”問(wèn)題 RPC 調(diào)用使用的是短連接，每調(diào)用一次就會(huì)創(chuàng)建一個(gè) Socket 對(duì)象，致使 FinalReference 對(duì)象非常多， 因此，YoungGC 耗時(shí)增加。

• 對(duì)于“為什么 RPC 調(diào)用耗時(shí)長(zhǎng)短也會(huì)影響 YoungGC 的耗時(shí)？”問(wèn)題 由于 RPC 調(diào)用耗時(shí)長(zhǎng)的，同樣的線程數(shù)，調(diào)用的 QPS 就低，QPS 低自然創(chuàng)建的 Socket 對(duì)象就少，致使 FinalReference 對(duì)象少，因此，YoungGC 耗時(shí)相比就會(huì)小一些。

解決

理解了問(wèn)題產(chǎn)生的原理，解決問(wèn)題自然變得非常簡(jiǎn)單。

• 通用方法?

加上 ParallelRefProcEnabled 參數(shù)可以使得 Reference 在 GC 的時(shí)候多線程并行處理過(guò)程，自然耗時(shí)就會(huì)降下來(lái)。

//ParallelRefProcEnabled 參數(shù) -XX:+ParallelRefProcEnabled

• 減少 GC 的 Reference 數(shù)量?

減少 GC 的 Reference 方法比較多，不同的案例不同的處理方法，能減少 GC 的 Reference 數(shù)量就好。 這里也很簡(jiǎn)單，RPC 調(diào)用短連接改用長(zhǎng)鏈接，自然就能減少 GC 的 Reference 數(shù)量。 該案例就使用了這個(gè)方案，效果也很明顯，YoungGC 時(shí)間直接降低到了 14ms。

總結(jié)

本案例總結(jié)原因就是 RPC 使用短連接調(diào)用，導(dǎo)致 Socket 的 FinalReference 引用較多，致使 YoungGC 耗時(shí)較長(zhǎng)。因此，通過(guò)將短連接改成長(zhǎng)連接，減少了 Socket 對(duì)象的創(chuàng)建，從而減少 FinalReference，來(lái)降低 YoungGC 耗時(shí)。 在看本篇文章之前，你一定不會(huì)想到 JVM GC 處理 FinalReference 耗時(shí)這么長(zhǎng)；你也一定不會(huì)想到短連接還有影響 GC 耗時(shí)的壞處。 排查問(wèn)題的過(guò)程，很享受，不僅可以證明所學(xué)，也可以錘煉技術(shù)。

總結(jié)

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

如果覺(jué)得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。