作者：sneak
鏈接https://juejin.im/post/5ef800636fb9a07e66233884
來源：掘金

問題現(xiàn)象

在某個(gè)工作日，突然收到線上的服務(wù)告警，有大量的請求延時(shí)產(chǎn)生，查看線上服務(wù)發(fā)現(xiàn)基本上都是獲取數(shù)據(jù)庫連接超時(shí)，而且影響時(shí)間只有3~4秒鐘，服務(wù)又恢復(fù)了正常。隔了幾分鐘之后，又出現(xiàn)了大量的告警，還是影響3~4秒后又恢復(fù)正常。 由于我們是底層服務(wù)，被重多的上層服務(wù)所依賴，這么頻繁的異常波動(dòng)已經(jīng)嚴(yán)重影響到了業(yè)務(wù)使用。開始排查問題

排查過程

DB的影響？

當(dāng)?shù)谝淮胃婢a(chǎn)生時(shí)，第一反應(yīng)是可能上層服務(wù)有大量的接口調(diào)用，并且涉及到一些復(fù)雜的SQL查詢導(dǎo)致數(shù)據(jù)庫連接數(shù)不夠用，但是在分析了接口調(diào)用情況后發(fā)現(xiàn)異常前后的請求并沒有明顯的變化，排除突發(fā)流量造成的影響

查詢DB情況，負(fù)載良好，無慢查詢，排除DB造成的影響

容器或JVM的影響？

排除了DB的影響之后，再往上排查容器的影響 我們再次回過頭看異常告警，發(fā)現(xiàn)在每一波告警的時(shí)間段內(nèi)，基本上都是同一個(gè)容器IP所產(chǎn)生，這個(gè)時(shí)候基本上已經(jīng)有80%的概率是GC的問題了。 查詢告警時(shí)間段內(nèi)的容器CPU負(fù)載正常。再看JVM的內(nèi)存和GC情況，發(fā)現(xiàn)整個(gè)內(nèi)存使用曲線是像下面這樣：

Heap

Old Gen

從上圖可以發(fā)現(xiàn)內(nèi)存中存在長時(shí)間被引用，無法被YongGC所回收的對象，并且對象大小一直在增長。直到Old Gen被堆滿之后觸發(fā)Full GC后對象才會(huì)回收。

臨時(shí)措施

現(xiàn)在問題已經(jīng)找到了，到目前為止只是3臺(tái)實(shí)例觸發(fā)了FullGC，但是在查看其它實(shí)例內(nèi)存使用情況時(shí)，發(fā)現(xiàn)基本上所有的實(shí)例Old Gen都快到達(dá)臨界點(diǎn)了。所以臨時(shí)解決方案是保留一臺(tái)實(shí)例現(xiàn)場，滾動(dòng)重啟其它所有的實(shí)例，避免大量的實(shí)例同時(shí)進(jìn)行FullGC。否則很可能導(dǎo)致服務(wù)雪崩。

原本服務(wù)是有設(shè)置jvm監(jiān)控告警的，理論上來說當(dāng)內(nèi)存使用率達(dá)到一定值時(shí)會(huì)有告警通知，但是由于一次服務(wù)遷移導(dǎo)致告警配置失效，沒有提前發(fā)現(xiàn)問題。

問題分析

什么對象沒有被回收？

目前了解到的情況： 內(nèi)存無法被YoungGC回收，且無限增加，只有FullGC才能夠回收這批對象

jmap -histo:live pid

先簡單在線上觀察了一波，排第2的HashMap$Node看起來比較異常，但是看不出更詳細(xì)的情況了。最好的辦法還是將內(nèi)存快照dump出來，使用MAT分析一波

jmap -dump:format=b,file=filename pid

使用MAT打開之后，可以發(fā)現(xiàn)很明顯的問題：

class com.mysql.cj.jdbc.AbandonedConnectionCleanupThread

這個(gè)類占用了80%以上的內(nèi)存，那么這個(gè)類是干嘛的呢？ 看類名就知道，應(yīng)該是MySQL Driver中用來清理過期連接的一個(gè)線程。讓我們看一下源碼：

這個(gè)類是一個(gè)單例，會(huì)且僅會(huì)開一個(gè)線程，用來清理那些沒有被顯式的關(guān)閉的數(shù)據(jù)庫連接。

可以看到這個(gè)類里面維護(hù)了一個(gè)Set

private static final Set<ConnectionFinalizerPhantomReference> connectionFinalizerPhantomRefs = ConcurrentHashMap.newKeySet();

對應(yīng)我們上面看到的內(nèi)存占用率排第二的HashMap$Node，基本上可以確定大概率是這里存在內(nèi)存泄露了。在MAT上使用list_object確認(rèn)一發(fā)：

果然沒錯(cuò)，罪魁禍?zhǔn)渍业搅?#xff01; 那么它里面存的是啥東西呢？ 為什么一直增長且無法被YoungGC回收？看名字
ConnectionFinalizerPhantomReference 我們可以猜到它里面保存的應(yīng)該是數(shù)據(jù)庫連接的phantom引用

什么是phantom reference? 當(dāng)一個(gè)對象只有phantom reference引用時(shí)，則會(huì)在虛擬機(jī)GC時(shí)被回收，同時(shí)會(huì)將phantom reference的對象放入一個(gè)referenceQueue中。

讓我們來跟蹤源碼確認(rèn)一下

果然是PhantomReference，里面存放的是創(chuàng)建的MySQL連接，看一下是在哪里被放進(jìn)來的：

可以看到，每次創(chuàng)建一個(gè)新的數(shù)據(jù)庫連接時(shí)，都會(huì)將創(chuàng)建的連接包裝成PhantomReference后放入
connectionFinalizerPhantomRefs中，然后這個(gè)清理線程會(huì)在一個(gè)無限循環(huán)中，獲取referenceQueue中的連接并關(guān)閉。

只有在 connection對象 沒有其它的引用，僅存在phantom reference時(shí)，才能夠被GC，并且放入referenceQueue中

為什么Connection會(huì)無限增長？

現(xiàn)在問題找到了，數(shù)據(jù)庫連接被創(chuàng)建之后，則會(huì)放入
connectionFinalizerPhantomRefs中，但是由于某種原因，連接前期正常使用，經(jīng)過了多次minor GC都沒有被回收，晉升到了老年代。但是一段時(shí)間過后，由于某種原因連接失效，導(dǎo)致連接池又新建了連接。

我們項(xiàng)目用的數(shù)據(jù)庫連接池是Druid，以下為連接池配置：

可以看到是設(shè)置了keepAlive，且
minEvictableIdleTimeMillis設(shè)置的是5分鐘，連接初始化之后，在DB請求數(shù)沒有頻繁的波動(dòng)時(shí)，連接池應(yīng)該都是維護(hù)著最小的30個(gè)連接，且會(huì)在連接空閑時(shí)間超過5分鐘時(shí)進(jìn)行一次keepAlive操作:

理論上來說，連接池是不會(huì)頻繁的創(chuàng)建連接的，除非有活躍連接很少，且存在波動(dòng)，并且keepAlive操作沒有生效，在連接池進(jìn)行keepAlive操作時(shí)，MySQL連接就已經(jīng)失效，那么則會(huì)丟棄這個(gè)無效連接，下次再重建。

下面就是驗(yàn)證這個(gè)猜想，我們首先查看我們的活躍連接數(shù)，發(fā)現(xiàn)在大部分時(shí)候，單實(shí)例的數(shù)據(jù)庫的活躍連接數(shù)都在3~20個(gè)左右波動(dòng)，并且業(yè)務(wù)上還存在定時(shí)任務(wù)，每隔30分鐘~1個(gè)小時(shí)會(huì)有大量的DB請求。 Druid既然有每隔5分鐘有心跳行為，那為什么連接還會(huì)失效？ 最大的可能是MySQL服務(wù)端的操作，MySQL默認(rèn)服務(wù)端的wait_timeout是8小時(shí)，難道是有變更對應(yīng)的配置？

show global variables like '%timeout%'

果然，數(shù)據(jù)庫的超時(shí)時(shí)間被設(shè)置成了5分鐘！那么問題就很明顯了。

結(jié)論

空閑連接依賴于Druid的keepAlive定時(shí)任務(wù)來進(jìn)行心跳檢測和keepAlive，定時(shí)任務(wù)默認(rèn)每60秒檢測一次，并且只有當(dāng)連接的空閑時(shí)間大于minEvictableIdleTimeMillis時(shí)才會(huì)進(jìn)行心跳檢測。

由于minEvictableIdleTimeMillis被設(shè)置為了5分鐘，理論上空閑連接會(huì)在5分鐘±60秒的時(shí)間區(qū)間內(nèi)進(jìn)行心跳檢測。但是由于MySQL服務(wù)端的超時(shí)時(shí)間只有5分鐘，所以大概率當(dāng)Druid進(jìn)行keepAlive操作時(shí)連接已經(jīng)失效了。

由于數(shù)據(jù)庫的活躍連接是波動(dòng)的，且min-idle設(shè)置的是30，活躍連接處于波峰時(shí)，需要?jiǎng)?chuàng)建大量的連接，并且維護(hù)在連接池中。但是當(dāng)活躍降到低谷時(shí)，大量的連接由于keepAlive失敗，從連接池中被移除。周而復(fù)始。

每次創(chuàng)建連接時(shí)，又會(huì)將Connection對象放入入connectionFinalizerPhantomRefs中，并且由于創(chuàng)建完之后連接是處于活躍狀態(tài)，短時(shí)間內(nèi)不會(huì)被miniorGC所回收，直至?xí)x升到老年代。導(dǎo)致這個(gè)SET越來越大。

解決

知道問題的產(chǎn)生原因，要解決就很簡單了，將
minEvictableIdleTimeMillis設(shè)置為3分鐘，保證keepAlive的有效性，避免一直重建連接即可。

總結(jié)

以上是生活随笔為你收集整理的weblogic连接池不释放问题解决_数据库连接池引起的FullGC问题，看我如何一步步排查、分析、解决...的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

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